mirror of
https://github.com/okieselbach/AutopilotMonitor.git
synced 2026-10-25 13:10:13 +00:00
Compare commits
13 Commits
| Author | SHA1 | Date | |
|---|---|---|---|
| 990641b19e | |||
| 3ca2f3b499 | |||
| b9fa760404 | |||
| ab61839685 | |||
| 34fd40c3ad | |||
| a0eb1b9e35 | |||
| 9d677db2a8 | |||
| c728a0bd41 | |||
| 64336c0c89 | |||
| 59c944618b | |||
| 3c25172dfb | |||
| eda61eaade | |||
| 04b1a7c6e7 |
+1
-1
Submodule .claude/commands updated: 3f98090747...2866e07882
@@ -0,0 +1,127 @@
|
||||
---
|
||||
type: concept
|
||||
title: CMTrace Time Resolution — Per-Line Self-Anchoring
|
||||
description: How the agent converts bias-less CMTrace local times to UTC without trusting any process's timezone belief — each provably fresh line anchors its own offset against the agent clock on the 15-minute grid; everything not provably fresh falls back uniformly and says so.
|
||||
resource: src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime
|
||||
tags: [agent, ime, cmtrace, timestamps, timezone, calibration, provenance]
|
||||
timestamp: 2026-08-20
|
||||
---
|
||||
|
||||
# Problem
|
||||
|
||||
A CMTrace line carries local time and no offset — IME 1.104 writes `DateTime.Now.TimeOfDay`
|
||||
in both of its trace listeners. Converting such a line with the reader's own
|
||||
`TimeZoneInfo.Local` silently assumes the writing and reading processes agree on the zone.
|
||||
They do not: each caches its zone at process start and follows neither a later `tzutil` nor
|
||||
a Windows auto-timezone change. The error is `Offset_writer − Offset_reader` — zero only
|
||||
when both believe the same thing, right or wrong. Field measurement over 11,068 sessions
|
||||
found 26 sessions with a real error, from +1 h to −17 h.
|
||||
|
||||
Two designs failed before this one:
|
||||
|
||||
* **Fix the reader's belief** (`TimeZoneInfo.ClearCachedData`, live OS offset): makes the
|
||||
agent isolated-correct and thereby breaks the majority of sessions, where two equally
|
||||
stale beliefs cancel.
|
||||
* **One measured offset per file** (agent 2.0.1410, reverted in `04b1a7c6`): a single log
|
||||
file holds lines from multiple writer *eras*. `AgentExecutor.log` is written by
|
||||
short-lived child processes whose zone belief flips per process — interleaved in one
|
||||
file, and flipping *back* (fixture:
|
||||
`tests/fixtures/cmtrace-logs/agentexecutor-two-writer-eras-v1.cmtrace`). Any cross-line
|
||||
anchor — per file, or nearest-in-write-order — applies one era's offset to the other
|
||||
era's lines. In the field this shifted `script_started` events by −9 h against their
|
||||
correct completions.
|
||||
|
||||
# Schema
|
||||
|
||||
The resolution rule, in order:
|
||||
|
||||
1. **Writer-declared bias** (`+480` suffix): authoritative, used as-is. Never a calibration
|
||||
anchor — it needs no measurement and must not overwrite one.
|
||||
2. **Per-line self-anchoring** — only for lines read in a *provably fresh* pass:
|
||||
|
||||
```
|
||||
offset_line = round((local − agentUtcNow) / 15 min) · 15 min
|
||||
lineUtc = local − offset_line
|
||||
```
|
||||
|
||||
Every real UTC offset is a whole multiple of 15 minutes, so the rounding absorbs poll
|
||||
and flush latency. No cross-line state exists, so interleaved eras resolve line by
|
||||
line — the property the fixture test pins. The line's own timestamp still contributes
|
||||
sub-poll precision and ordering (two lines 6 ms apart stay 6 ms apart; a plain
|
||||
`occurredAt = now` could not do that). Guards: grid residual ≤ 2 min, offset within
|
||||
UTC−12 … UTC+14.
|
||||
3. **Uniform reader-zone fallback** for everything else: wrong in absolute terms whenever
|
||||
the writer held a different belief, but *self-consistent* — both ends of a duration are
|
||||
wrong by the same amount, so derived durations stay right. The revert's core lesson:
|
||||
partially corrected is strictly worse than uniformly wrong.
|
||||
|
||||
**Freshness** is what makes rule 2 sound, and it is strict:
|
||||
|
||||
* Every poll look at a file stamps `LastCheckedUtc` (`LogFilePositionTracker.MarkChecked`),
|
||||
including "no new data" and an empty first sight — so a file first seen empty
|
||||
(`AgentExecutor.log` appearing mid-enrollment) anchors from its very first content.
|
||||
* A pass's lines are fresh only if the file was previously observed *in this process* and
|
||||
the gap since the last look is ≤ `FreshLineMaxAge` (30 s — far above the 100 ms poll,
|
||||
far below the 13-minute zone where a line's *age* could round onto the offset grid).
|
||||
* A restart-restored position bookmark deliberately carries **no** freshness: the first
|
||||
pass after a restart reads downtime backlog and must never anchor.
|
||||
|
||||
**Provenance** (`sourceOffsetOrigin` in event DataJson): `bias` | `line-anchored` |
|
||||
`reader-zone-fallback` (plus retired `calibrated` from 2.0.1410 events). The applied
|
||||
offset is always recorded (`sourceOffsetMinutes`), the raw local time too
|
||||
(`sourceLocalTs`), so any event can be re-derived later. The per-*file* measurement still
|
||||
runs, purely observationally (`measuredWriterOffsetMinutes`, Info log when it disagrees
|
||||
with the process zone).
|
||||
|
||||
# Constraints
|
||||
|
||||
* An anchored line resolves to `now ± 2 min` *by construction*. The accepted edge: a
|
||||
freshly written line carrying a **replayed** old timestamp whose age is exactly
|
||||
N×15 min ± 2 min anchors to ≈now instead of its replayed past — bounded error, and
|
||||
sub-24 h replays are treated as current by the historic-replay guard anyway.
|
||||
* Snapshot readers (`StallProbeCollector`, `LogParserCollector`) cannot tail and therefore
|
||||
cannot prove freshness — they stay on the marked fallback. This is a documented limit,
|
||||
not an omission; sharing the per-file measurement with them would re-apply exactly what
|
||||
the revert removed.
|
||||
* Mixed pairs remain possible across a restart (start resolved from backlog fallback,
|
||||
completion line-anchored) and are recognizable via provenance.
|
||||
|
||||
# Backend regression tripwire
|
||||
|
||||
The backend watches for the failure mode this design eliminates. On every terminal ingest
|
||||
batch, the counter reconcile's existing event-partition scan additionally collects
|
||||
`Δ = ReceivedAt − OccurredUtc` per event, split by `Source == "ImeLogTracker"` versus the
|
||||
rest (`CmTraceSkewTripwire`, hooked in `EventIngestProcessor`). If
|
||||
`median(Δ_IME) − median(Δ_other)` is a clean 15-minute multiple (residual < 2 min — the
|
||||
same constants as the anchoring grid guard above) with ≥ 20 samples over ≥ 3 distinct
|
||||
upload batches per side, a `CmTraceTimeSkewRegression` ops event fires (category Agent,
|
||||
warning), carrying all numbers plus the session's `sourceOffsetOrigin` histogram.
|
||||
Bias-dominated sessions are suppressed (writer-declared offsets cannot be an anchoring
|
||||
regression); `measuredWriterOffsetMinutes` is never consulted (sticky after era
|
||||
flip-backs). Kill switch: app setting `CmTraceSkewTripwireDisabled`. Goal state: the event
|
||||
never fires — any hit is an anchoring case the per-line design misses, or a detector bug.
|
||||
|
||||
Device-clock problems (the customer-actionable cousin) are covered separately by the
|
||||
`clock_skew` analyze condition behind `ANALYZE-DEV-008`, which excludes IME-derived events
|
||||
precisely so an anchoring regression can never surface as a customer finding.
|
||||
|
||||
# Citations
|
||||
|
||||
* `CmTraceOffsetCalibrator.TryMeasureOffset` — the pure grid measurement, shared by
|
||||
anchoring and the observational per-file path.
|
||||
* `CmTraceSkewTripwire` + `CmTraceSkewTripwireTests` — the backend tripwire above.
|
||||
* `RuleEngine.ConditionEvaluators.EvaluateClockSkewCondition` + `RuleEngineClockSkewTests`
|
||||
— the customer-facing device-clock metrics (batch-median frames, spool-spread filter,
|
||||
plateau step detection, end-state persistence).
|
||||
* `ImeLogTracker.LogProcessing.cs` `ResolveEntryUtc` — the resolution order above.
|
||||
* `ImeLogTrackerLineAnchoringTests` — resolves-to-T across writer beliefs, interleaved
|
||||
eras in one chunk, freshness boundaries (first sight, empty first sight, poll gap,
|
||||
restart restore), the grid-replay edge, and the field fixture replayed at production
|
||||
poll cadence.
|
||||
* `CmTraceCalibratorFileIsolationTests` — pins per-file isolation of the observational
|
||||
measurement (session e9753578 logged a cross-file pairing the committed code could not
|
||||
be shown to produce; the mechanism remains open, the resolution path is immune by
|
||||
design, and `CalibrateFrom` logs the anchor timestamp as a tripwire).
|
||||
* `tasks/todo.md` (2026-08-20) — full evidence trail: field measurements, the revert,
|
||||
the two-writer-era fixture, and the disproven foreign-binary hypothesis (the SHA
|
||||
mismatch was the known release race against the 5-minute AdminConfiguration cache).
|
||||
@@ -0,0 +1,84 @@
|
||||
---
|
||||
type: concept
|
||||
title: Send-Time Frame Separation (X-Send-Time-Utc)
|
||||
description: One device-clock send timestamp per upload batch splits ReceivedAt − OccurredUtc into pure spool delay and pure device-vs-server clock offset — turning clock diagnostics from median statistics into direct per-request measurement.
|
||||
resource: src/Backend/AutopilotMonitor.Functions/Functions/Ingest/IngestTelemetryFunction.cs
|
||||
tags: [backend, agent, ingest, timestamps, clock-skew, telemetry, provenance]
|
||||
timestamp: 2026-08-21
|
||||
---
|
||||
|
||||
# Problem
|
||||
|
||||
Events carry two time anchors: `OccurredUtc` (device clock at emission) and `ReceivedAt`
|
||||
(server clock at ingest). Their difference conflates two physically distinct phenomena:
|
||||
|
||||
* **Spool delay** — the event waited offline or in retry backoff before upload. Expected,
|
||||
harmless, minutes to hours.
|
||||
* **Device-vs-server clock offset** — the actual diagnostic signal.
|
||||
|
||||
A uniform spool backlog (events emitted close together, uploaded after an outage) is
|
||||
indistinguishable from a clock offset in that delta; a draining backlog fakes a clock jump
|
||||
ramp. Every consumer had to filter this statistically (spread caps, plateau guards,
|
||||
persistence tests) — and the first field clock-jump measurement failed exactly on this
|
||||
ambiguity.
|
||||
|
||||
# Schema
|
||||
|
||||
The agent stamps one header per upload attempt (`BackendTelemetryUploader`):
|
||||
|
||||
```
|
||||
X-Send-Time-Utc: <DateTime.UtcNow, ISO-8601 round-trip>
|
||||
```
|
||||
|
||||
Per **attempt**, not per batch content: a retry after backoff is a new send moment. The
|
||||
ingest function parses it (`ParseSendTimeHeader`: round-trip parse, UTC-normalized, values
|
||||
before year 2000 rejected as garbage — deliberately **no upper clamp**, a future-dated
|
||||
send time IS the clock-error measurement), and `StampServerFields` writes it as `SentAt`
|
||||
onto every event of the request — server-stamped, request-level, never trusted per-event
|
||||
from the wire. Stored as the nullable `SentAt` column on Events (absent for pre-header
|
||||
agents), mapped back everywhere events are read, exposed as `sentAt` in the `fields=`
|
||||
projection and verbatim on the raw endpoints.
|
||||
|
||||
The separation is then exact:
|
||||
|
||||
```
|
||||
SentAt − OccurredUtc = pure spool delay (both device frame; offset cancels)
|
||||
ReceivedAt − SentAt = network latency + clock offset (the only frame crossing)
|
||||
```
|
||||
|
||||
Network latency is seconds; anything beyond is device clock error, per request, no
|
||||
statistics required.
|
||||
|
||||
# Consumers
|
||||
|
||||
* **`clock_skew` analyze condition** (ANALYZE-DEV-008): batches whose events carry
|
||||
`SentAt` measure the batch offset directly as `SentAt − ReceivedAt` — spool-immune by
|
||||
construction, so the spread cap and the IME/clamped exclusions are unnecessary there
|
||||
(no event timestamps are read at all; IME-only sessions become measurable). Batches
|
||||
without `SentAt` keep the legacy per-event median + spread-cap path. Downstream logic
|
||||
(stability check, plateau step detection, end-state persistence) is shared; evidence
|
||||
carries `sentAtBatchCount`.
|
||||
* **`CmTraceSkewTripwire` deliberately unchanged**: `median(Δ_IME) − median(Δ_other)`
|
||||
cancels the device clock offset as common mode — send time adds nothing to that
|
||||
differential measurement.
|
||||
|
||||
# Constraints
|
||||
|
||||
* `SentAt` comes from the same device wall clock as the event timestamps — a clock jump
|
||||
between emission and send lands in the spool-delay term. That is the intended place for
|
||||
it to become visible, not a defect.
|
||||
* Signals and DecisionTransitions do not carry `SentAt` (no consumer); the header is
|
||||
request-level, so extending them later is a storage-only change.
|
||||
* Fleet coverage grows with agent rollout; all analyses must treat `SentAt == null`
|
||||
(legacy rows, old agents) as "legacy path", never as zero.
|
||||
|
||||
# Citations
|
||||
|
||||
* `BackendTelemetryUploader.UploadBatchAsync` — header stamping per attempt.
|
||||
* `IngestTelemetryFunction.ParseSendTimeHeader` + `IngestTelemetryFunctionTests` — parse
|
||||
contract incl. the no-upper-clamp decision.
|
||||
* `EventIngestProcessor.StampServerFields` + `IngestCriticalPathTests` — server-side
|
||||
stamping, forged per-event values overridden.
|
||||
* `RuleEngine.ConditionEvaluators.EvaluateClockSkewCondition` + `RuleEngineClockSkewTests`
|
||||
— the two measurement paths (the backlog-alias test pair pins why SentAt exists).
|
||||
* `tasks/todo.md` P14 (2026-08-21) — decision trail incl. why the tripwire stays as is.
|
||||
@@ -27,6 +27,7 @@ https://docs.autopilotmonitor.com (separate repository).
|
||||
* [ESP Completion Starvation — the sits-d Cloud-PC complex](agent/post-reboot-completion-recovery.md) - Why a SkipUser=true flow (no user ESP page → no Shell-Core 62407, no AccountSetup registry) left the completion gate satisfied but never evaluated — five Cloud PCs idled six hours at "waiting on: hello_resolution" — and the fix: the observed skip stands in for the final-exit evidence in the IME user-session completion attempt. Plus the two adjacent defects fixed alongside: the edge-only user-apps-settled synthesis (now level-triggered) and the never-wired Shell-Core restart replay (now Hello-wizard-only, with the reasoning why a replayed 62407 must never reach the reducer).
|
||||
* [Secure Boot CA-2023 Detection](agent/secureboot-ca2023-detection.md) - Why ANALYZE-SEC-001 v3 reads the UEFI db/KEK variables directly instead of trusting the SecureBoot\Servicing registry, and how the one-sided uefiCa2023FirmwareConfirmed marker plus a not_exists precondition give absence-tolerant suppression across old and new agents.
|
||||
* [Continue-Anyway Observation Mode](agent/continue-anyway-observation.md) - EnableEspContinueAnywayObservation (ConfigVersion 37, operator-set): Device-phase ESP terminal failures on Continue-Anyway profiles get a bounded 60-min observation instead of an immediate hard fail; the DAD-validated real-user desktop + Hello gate detect the true end, the session completes Succeeded + EspSoftFailure (amber "with issues" badge), expiry un-defangs to the original esp_terminal_failure.
|
||||
* [CMTrace Time Resolution](agent/cmtrace-time-resolution.md) - Converting bias-less CMTrace local times to UTC without trusting any process's timezone belief: per-line self-anchoring on the 15-minute offset grid for provably fresh lines, uniform marked reader-zone fallback for backlog, and the provenance vocabulary (bias / line-anchored / reader-zone-fallback) that keeps every event re-derivable.
|
||||
* [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.
|
||||
* [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.
|
||||
@@ -41,6 +42,7 @@ https://docs.autopilotmonitor.com (separate repository).
|
||||
# Backend
|
||||
|
||||
* [Business Timestamps](backend/business-timestamps.md) - Why the Azure Tables system Timestamp is never authoritative (migrations reset it), and the OccurredUtc + RowKey-decode compensation for AuditLogs/OpsEvents/Events after the 2026-07-18 migration.
|
||||
* [Send-Time Frame Separation](backend/send-time-frame-separation.md) - One device-clock send timestamp per upload batch (X-Send-Time-Utc → SentAt on Events) splits ReceivedAt − OccurredUtc into pure spool delay and pure device-vs-server clock offset; the clock_skew condition measures SentAt batches directly (spool-immune), the CMTrace tripwire deliberately stays on its differential math.
|
||||
* [OOBE Bootstrap go-Code Flow](backend/oobe-bootstrap-go-flow.md) - The bootstrap short-code lifecycle (portal-created session → `irm go.autopilotmonitor.com/CODE | iex` at Shift+F10 → GetBootstrapScriptFunction), the always-HTTP-200 text/plain contract, the two-line injection defense (GUID/URL/expiry validator + single-quoted PS literals, golden-pinned against the legacy TS template), and the per-IP rate-limit story behind Front Door.
|
||||
* [Device Journeys & First-Time-Right](backend/device-journeys.md) - How a device's terminal enrollment attempts are grouped into journeys (trim+casefold device key with junk-serial exclusion, first-success end, 30-day gap, WhiteGlove = one attempt), the DeviceHistories chain with its tombstone-driven deleted-session pruning, the additive daily FTR aggregates, and the banner/fleet/MCP surfaces.
|
||||
* [Enrollment Time Attribution](backend/time-attribution.md) - How a terminal session's authoritative wall clock (DurationSeconds, WhiteGlove pause excluded) is partitioned into named segments with an explicit unattributed remainder, ESP-blocking apps as positive evidence with "up to" what-if bounds, reboot spans from event gaps, and the breakdown/aggregate tables the sweep maintains.
|
||||
|
||||
@@ -1,7 +1,15 @@
|
||||
# Log
|
||||
|
||||
## 2026-08-21
|
||||
|
||||
* **New**: `backend/send-time-frame-separation.md` — P14: the agent stamps one device-clock send timestamp per upload attempt (`X-Send-Time-Utc`), the ingest function server-stamps it as `SentAt` on every event of the request. `SentAt − OccurredUtc` is pure spool delay, `ReceivedAt − SentAt` is network + device-vs-server clock offset — the two were indistinguishable before and had to be separated statistically. The `clock_skew` condition measures SentAt-carrying batches directly (spool-immune, no spread cap, IME-only sessions become measurable; evidence carries `sentAtBatchCount`), legacy batches keep the median path; the CMTrace tripwire deliberately stays on its differential math (common-mode clock offset cancels there).
|
||||
|
||||
## 2026-08-20
|
||||
|
||||
* **Update**: `agent/cmtrace-time-resolution.md` — new "Backend regression tripwire" section: the P6 split. Operator side: `CmTraceSkewTripwire` piggybacks on the terminal counter reconcile's partition scan (`Δ = ReceivedAt − OccurredUtc` per source, 15-min grid + 2-min residual, ≥20 samples / ≥3 distinct batches per side, bias-dominated sessions suppressed, `measuredWriterOffsetMinutes` never consulted) and emits the `CmTraceTimeSkewRegression` ops event — goal state: never fires; kill switch `CmTraceSkewTripwireDisabled`. Customer side: new `clock_skew` analyze condition source (`skewMetric: clock_jump | sustained_offset`, threshold in seconds, batch-median frames with spool-spread filter, plateau step detection, end-state persistence, IME-derived events excluded) behind the new built-in `ANALYZE-DEV-008` (300 s = the Kerberos/Entra 5-minute skew boundary) — the during-enrollment complement of ANALYZE-DEV-007's one-shot NTP check. P5 (agent-side observability event) is subsumed by the tripwire.
|
||||
|
||||
* **New**: `agent/cmtrace-time-resolution.md` — the era-aware answer to the CMTrace timezone skew: a bias-less line read in a provably fresh pass anchors its own UTC offset against the agent clock (15-minute grid, 2-minute residual), so interleaved writer eras in one file resolve line by line; everything not provably fresh keeps the uniform reader-zone fallback and says so via `sourceOffsetOrigin`. Freshness is a per-file `LastCheckedUtc` stamped on every poll look (empty first sights included) with a 30-second window, never restored across restarts. Replaces the reverted per-file offset application (04b1a7c6); the per-file measurement stays observational, now with the anchor timestamp logged as a tripwire for the still-unexplained e9753578 label/anchor crossing.
|
||||
|
||||
* **Update**: `agent/post-reboot-completion-recovery.md` — retitled to "ESP Completion Starvation — the sits-d Cloud-PC complex" and reframed on the evidence: the reboot was a red herring. The five stuck Cloud PCs carried `SkipUserStatusPage=True` (read 10+ times across three agent processes, `True` every time) and Windows honoured it — no user ESP page, hence no Shell-Core 62407 and no AccountSetup provisioning registry, verified over a six-hour uninterrupted post-reboot run with the watcher armed. Arm B of `ShouldTransitionToAwaitingHello` was open from the bootstrap onward, but every evaluation site hangs off a signal a skip-user flow cannot produce, and the `AdvisoryCompletion` backstop arms exclusively from an `EspExiting` signal — an open gate nobody knocks on. Fix: `HandleImeUserSessionCompletedV1` accepts the observed skip in place of the final-exit evidence (`skipUserExitEquivalent`; anchor + genuine IME completion + real-user desktop stay mandatory, WDP excluded). The knock deliberately lives on the IME edge, not desktop arrival — ordering-robust against Fix 10's AccountSetup bounce-back and semantically "user-phase work finished" rather than mid-install. `ClassicSkipUserEspUserSessionCompletionTests` replays the real 8110e262 ordering end to end. Docs and comments no longer claim an ESP-exit recovery that does not exist (stray duplicate summary in `ShellCoreTracker`, `ImeLogHost` restore-callback comment); the residual `SkipUser=false` exit-in-downtime gap is named honestly and surfaced by `ANALYZE-ESP-005` via `session_stalled` instead of being patched with an unorderable replay.
|
||||
|
||||
## 2026-08-19
|
||||
|
||||
@@ -0,0 +1,69 @@
|
||||
{
|
||||
"$schema": "../schema/analyze-rule.schema.json",
|
||||
"ruleId": "ANALYZE-DEV-008",
|
||||
"title": "Device Clock Wrong During Enrollment — Jump or Sustained Offset",
|
||||
"description": "The device's clock changed by five or more minutes mid-session (clock jump) or ran five or more minutes off server time for the whole session (sustained offset), measured against the server receive frame of every uploaded event. Complements ANALYZE-DEV-007, which is a one-shot NTP check at agent startup and misses devices where NTP was unreachable or the clock changed later. IME-log-derived events are excluded from the measurement.",
|
||||
"severity": "warning",
|
||||
"category": "device",
|
||||
"version": "1.0.0",
|
||||
"author": "Autopilot Monitor",
|
||||
"enabled": true,
|
||||
"evaluateOn": [
|
||||
"enrollment_end",
|
||||
"whiteglove_sealed"
|
||||
],
|
||||
"trigger": "single",
|
||||
"baseConfidence": 60,
|
||||
"confidenceThreshold": 50,
|
||||
"conditions": [
|
||||
{
|
||||
"signal": "clock_jump",
|
||||
"source": "clock_skew",
|
||||
"skewMetric": "clock_jump",
|
||||
"operator": "gte",
|
||||
"value": "300",
|
||||
"required": false
|
||||
},
|
||||
{
|
||||
"signal": "sustained_offset",
|
||||
"source": "clock_skew",
|
||||
"skewMetric": "sustained_offset",
|
||||
"operator": "gte",
|
||||
"value": "300",
|
||||
"required": false
|
||||
}
|
||||
],
|
||||
"confidenceFactors": [],
|
||||
"explanation": "This device's {{skewSummary}} (five-minute threshold). A clock that is off by five or more minutes breaks time-sensitive enrollment mechanisms: Kerberos tolerates at most 5 minutes of skew (Hybrid Join), Entra ID token validation allows about 5 minutes on token lifetimes, and freshly issued SCEP/PKCS certificates can be rejected as \"not yet valid\" when the clock is more than ~10 minutes behind the CA.\n\nUnlike ANALYZE-DEV-007 (a one-shot NTP comparison at agent startup), this finding is measured across the whole session against the server's receive time — it also catches devices where the NTP check could not run (UDP 123 blocked) or where the clock changed after startup (time sync correcting a wrong RTC, Windows auto-timezone, manual change).",
|
||||
"remediation": [
|
||||
{
|
||||
"title": "Fix the device clock and time source",
|
||||
"steps": [
|
||||
"Check the BIOS/RTC clock and the CMOS battery if the wrong time recurs on the same hardware.",
|
||||
"At OOBE, run 'w32tm /resync /force' (Shift+F10 command prompt) to sync with time.windows.com.",
|
||||
"Ensure UDP port 123 to time.windows.com is open in the deployment network.",
|
||||
"Review 'Set time automatically' and 'Set time zone automatically' behavior on the deployment image — automatic timezone changes mid-enrollment show up as clock jumps."
|
||||
]
|
||||
}
|
||||
],
|
||||
"relatedDocs": [
|
||||
{
|
||||
"title": "Microsoft Learn: Windows Autopilot known issues — device provisioning can fail (clock skew)",
|
||||
"url": "https://learn.microsoft.com/en-us/autopilot/known-issues"
|
||||
},
|
||||
{
|
||||
"title": "Microsoft Learn: Windows Autopilot requirements — Networking (NTP)",
|
||||
"url": "https://learn.microsoft.com/en-us/autopilot/requirements?tabs=networking"
|
||||
}
|
||||
],
|
||||
"markSessionAsFailedDefault": false,
|
||||
"tags": [
|
||||
"device",
|
||||
"clock-skew",
|
||||
"clock-jump",
|
||||
"time-sync",
|
||||
"kerberos",
|
||||
"certificates",
|
||||
"known-issue"
|
||||
]
|
||||
}
|
||||
+68
@@ -1516,6 +1516,74 @@
|
||||
"known-issue"
|
||||
]
|
||||
},
|
||||
{
|
||||
"ruleId": "ANALYZE-DEV-008",
|
||||
"title": "Device Clock Wrong During Enrollment — Jump or Sustained Offset",
|
||||
"description": "The device's clock changed by five or more minutes mid-session (clock jump) or ran five or more minutes off server time for the whole session (sustained offset), measured against the server receive frame of every uploaded event. Complements ANALYZE-DEV-007, which is a one-shot NTP check at agent startup and misses devices where NTP was unreachable or the clock changed later. IME-log-derived events are excluded from the measurement.",
|
||||
"severity": "warning",
|
||||
"category": "device",
|
||||
"version": "1.0.0",
|
||||
"author": "Autopilot Monitor",
|
||||
"enabled": true,
|
||||
"evaluateOn": [
|
||||
"enrollment_end",
|
||||
"whiteglove_sealed"
|
||||
],
|
||||
"trigger": "single",
|
||||
"baseConfidence": 60,
|
||||
"confidenceThreshold": 50,
|
||||
"conditions": [
|
||||
{
|
||||
"signal": "clock_jump",
|
||||
"source": "clock_skew",
|
||||
"skewMetric": "clock_jump",
|
||||
"operator": "gte",
|
||||
"value": "300",
|
||||
"required": false
|
||||
},
|
||||
{
|
||||
"signal": "sustained_offset",
|
||||
"source": "clock_skew",
|
||||
"skewMetric": "sustained_offset",
|
||||
"operator": "gte",
|
||||
"value": "300",
|
||||
"required": false
|
||||
}
|
||||
],
|
||||
"confidenceFactors": [],
|
||||
"explanation": "This device's {{skewSummary}} (five-minute threshold). A clock that is off by five or more minutes breaks time-sensitive enrollment mechanisms: Kerberos tolerates at most 5 minutes of skew (Hybrid Join), Entra ID token validation allows about 5 minutes on token lifetimes, and freshly issued SCEP/PKCS certificates can be rejected as \"not yet valid\" when the clock is more than ~10 minutes behind the CA.\n\nUnlike ANALYZE-DEV-007 (a one-shot NTP comparison at agent startup), this finding is measured across the whole session against the server's receive time — it also catches devices where the NTP check could not run (UDP 123 blocked) or where the clock changed after startup (time sync correcting a wrong RTC, Windows auto-timezone, manual change).",
|
||||
"remediation": [
|
||||
{
|
||||
"title": "Fix the device clock and time source",
|
||||
"steps": [
|
||||
"Check the BIOS/RTC clock and the CMOS battery if the wrong time recurs on the same hardware.",
|
||||
"At OOBE, run 'w32tm /resync /force' (Shift+F10 command prompt) to sync with time.windows.com.",
|
||||
"Ensure UDP port 123 to time.windows.com is open in the deployment network.",
|
||||
"Review 'Set time automatically' and 'Set time zone automatically' behavior on the deployment image — automatic timezone changes mid-enrollment show up as clock jumps."
|
||||
]
|
||||
}
|
||||
],
|
||||
"relatedDocs": [
|
||||
{
|
||||
"title": "Microsoft Learn: Windows Autopilot known issues — device provisioning can fail (clock skew)",
|
||||
"url": "https://learn.microsoft.com/en-us/autopilot/known-issues"
|
||||
},
|
||||
{
|
||||
"title": "Microsoft Learn: Windows Autopilot requirements — Networking (NTP)",
|
||||
"url": "https://learn.microsoft.com/en-us/autopilot/requirements?tabs=networking"
|
||||
}
|
||||
],
|
||||
"markSessionAsFailedDefault": false,
|
||||
"tags": [
|
||||
"device",
|
||||
"clock-skew",
|
||||
"clock-jump",
|
||||
"time-sync",
|
||||
"kerberos",
|
||||
"certificates",
|
||||
"known-issue"
|
||||
]
|
||||
},
|
||||
{
|
||||
"ruleId": "ANALYZE-ENRL-001",
|
||||
"title": "Enrollment Failed",
|
||||
|
||||
@@ -169,7 +169,12 @@
|
||||
"source": {
|
||||
"type": "string",
|
||||
"description": "Source of the signal.",
|
||||
"enum": ["event_type", "event_data", "event_data_array", "phase_duration", "event_count", "app_install_duration", "event_correlation"]
|
||||
"enum": ["event_type", "event_data", "event_data_array", "phase_duration", "event_count", "app_install_duration", "event_correlation", "clock_skew"]
|
||||
},
|
||||
"skewMetric": {
|
||||
"type": "string",
|
||||
"description": "For clock_skew only: which device-clock metric to evaluate. clock_jump = persistent step in the device's clock frame mid-session; sustained_offset = whole session ran on a clock off by at least the threshold. value is the threshold in seconds; operator is limited to gt/gte on the magnitude. IME-log-derived events are excluded from the measurement.",
|
||||
"enum": ["clock_jump", "sustained_offset"]
|
||||
},
|
||||
"eventType": {
|
||||
"type": "string",
|
||||
|
||||
+109
@@ -0,0 +1,109 @@
|
||||
using System;
|
||||
using System.Collections.Generic;
|
||||
using System.IO;
|
||||
using System.Threading;
|
||||
using System.Threading.Tasks;
|
||||
using AutopilotMonitor.Agent.V2.Core.Logging;
|
||||
using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime;
|
||||
using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
using Xunit;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
{
|
||||
/// <summary>
|
||||
/// Pins the per-FILE isolation of the offset measurement across a full read cycle.
|
||||
///
|
||||
/// <para>
|
||||
/// Background (2026-08-20, session e9753578): the field showed "+02:00 measured for
|
||||
/// IntuneManagementExtension.log" although that file held no +2-era line — the anchor had
|
||||
/// crossed file boundaries. The committed code was proven innocent (this very scenario is
|
||||
/// green here); the leak lived in a binary built from an uncommitted tree. This test keeps
|
||||
/// the property pinned so a real regression of the file scoping can never ship silently
|
||||
/// again — it replays the exact field pass structure: a NEW file appearing mid-run with a
|
||||
/// different writer era than the file already being tailed.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public sealed class CmTraceCalibratorFileIsolationTests
|
||||
{
|
||||
private static readonly DateTime T0 = new DateTime(2026, 8, 20, 12, 13, 0, DateTimeKind.Utc);
|
||||
|
||||
private static List<ImeLogPattern> Patterns() => new List<ImeLogPattern>
|
||||
{
|
||||
new ImeLogPattern
|
||||
{
|
||||
PatternId = "T-MARK", Category = "always", Enabled = true,
|
||||
Pattern = @"marker (?<n>\d+)",
|
||||
Action = "noop",
|
||||
Parameters = new Dictionary<string, string>(),
|
||||
},
|
||||
};
|
||||
|
||||
private static string Line(string message, DateTime utcInstant, TimeSpan writerOffset)
|
||||
{
|
||||
var local = utcInstant + writerOffset;
|
||||
return $"<![LOG[{message}]LOG]!><time=\"{local:HH:mm:ss.fffffff}\" date=\"{local:M-d-yyyy}\" " +
|
||||
"component=\"X\" context=\"\" type=\"1\" thread=\"1\" file=\"\">";
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task NewFileWithOtherEra_MustNotRecalibrateTheOldFile()
|
||||
{
|
||||
var pdt = TimeSpan.FromHours(-7); // IME service era
|
||||
var cest = TimeSpan.FromHours(2); // fresh child-process era
|
||||
|
||||
using var tmp = new TempDirectory();
|
||||
var now = T0;
|
||||
var tracker = new ImeLogTracker(
|
||||
logFolder: tmp.Path,
|
||||
patterns: Patterns(),
|
||||
logger: new AgentLogger(tmp.Path, AgentLogLevel.Info));
|
||||
try
|
||||
{
|
||||
tracker.UtcNowProvider = () => now;
|
||||
var imeLog = Path.Combine(tmp.Path, "IntuneManagementExtension.log");
|
||||
var execLog = Path.Combine(tmp.Path, "AgentExecutor.log");
|
||||
|
||||
// Pass 1: IME.log first sight (no calibration).
|
||||
File.AppendAllText(imeLog, Line("marker 1", now, pdt) + Environment.NewLine);
|
||||
await tracker.CheckLogFilesAsync(CancellationToken.None);
|
||||
|
||||
// Pass 2: IME.log grew -> measures -7.
|
||||
now = T0.AddSeconds(10);
|
||||
File.AppendAllText(imeLog, Line("marker 2", now, pdt) + Environment.NewLine);
|
||||
await tracker.CheckLogFilesAsync(CancellationToken.None);
|
||||
|
||||
TimeSpan imeMeasured;
|
||||
Assert.True(tracker.OffsetCalibrator.TryGetOffset("IntuneManagementExtension.log", out imeMeasured));
|
||||
Assert.Equal(pdt, imeMeasured);
|
||||
|
||||
// Pass 3: AgentExecutor.log appears for the FIRST time with fresh +2-era lines
|
||||
// while IME.log grows too — the exact field pass structure. The +2 anchor must
|
||||
// never land under IME.log's key.
|
||||
now = T0.AddSeconds(20);
|
||||
File.AppendAllText(execLog, Line("marker 3", now, cest) + Environment.NewLine);
|
||||
File.AppendAllText(imeLog, Line("marker 4", now, pdt) + Environment.NewLine);
|
||||
await tracker.CheckLogFilesAsync(CancellationToken.None);
|
||||
|
||||
Assert.True(tracker.OffsetCalibrator.TryGetOffset("IntuneManagementExtension.log", out imeMeasured));
|
||||
Assert.Equal(pdt, imeMeasured);
|
||||
|
||||
// Pass 4: both grow — each file measures its own writer's era.
|
||||
now = T0.AddSeconds(30);
|
||||
File.AppendAllText(execLog, Line("marker 5", now, cest) + Environment.NewLine);
|
||||
File.AppendAllText(imeLog, Line("marker 6", now, pdt) + Environment.NewLine);
|
||||
await tracker.CheckLogFilesAsync(CancellationToken.None);
|
||||
|
||||
TimeSpan execMeasured;
|
||||
Assert.True(tracker.OffsetCalibrator.TryGetOffset("AgentExecutor.log", out execMeasured));
|
||||
Assert.Equal(cest, execMeasured);
|
||||
Assert.True(tracker.OffsetCalibrator.TryGetOffset("IntuneManagementExtension.log", out imeMeasured));
|
||||
Assert.Equal(pdt, imeMeasured);
|
||||
}
|
||||
finally
|
||||
{
|
||||
tracker.Dispose();
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
+441
@@ -0,0 +1,441 @@
|
||||
using System;
|
||||
using System.Collections.Generic;
|
||||
using System.IO;
|
||||
using System.Threading;
|
||||
using System.Threading.Tasks;
|
||||
using AutopilotMonitor.Agent.V2.Core.Logging;
|
||||
using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime;
|
||||
using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
|
||||
using AutopilotMonitor.Shared.Logging;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
using Xunit;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
{
|
||||
/// <summary>
|
||||
/// Per-line self-anchoring — the era-aware successor to the reverted per-file offset
|
||||
/// application (04b1a7c6).
|
||||
///
|
||||
/// <para>
|
||||
/// The property under test: a line read in a provably FRESH pass resolves to the instant it
|
||||
/// was written, whatever timezone its writer believed — and neighbouring lines from writers
|
||||
/// with DIFFERENT beliefs each resolve to their own era, because no cross-line state is
|
||||
/// involved. That interleaving (fixture: AgentExecutor.log with PDT and CEST children in one
|
||||
/// file, flipping both ways) is exactly what broke every cross-line anchor design.
|
||||
/// </para>
|
||||
///
|
||||
/// <para>
|
||||
/// The freshness boundary is equally load-bearing: backlog (first sight, restart catch-up,
|
||||
/// stalled polls) must NEVER anchor, because an old line's age can round onto the 15-minute
|
||||
/// offset grid. Those paths keep the uniform reader-zone fallback.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public sealed class ImeLogTrackerLineAnchoringTests
|
||||
{
|
||||
private static readonly DateTime T0 = new DateTime(2026, 8, 20, 12, 13, 0, DateTimeKind.Utc);
|
||||
|
||||
private static List<ImeLogPattern> Patterns() => new List<ImeLogPattern>
|
||||
{
|
||||
new ImeLogPattern
|
||||
{
|
||||
PatternId = "T-ALL", Category = "always", Enabled = true,
|
||||
Pattern = @"marker (?<n>\d+)",
|
||||
Action = "noop",
|
||||
Parameters = new Dictionary<string, string>(),
|
||||
},
|
||||
};
|
||||
|
||||
/// <summary>A CMTrace line as a writer holding <paramref name="writerOffset"/> renders instant <paramref name="utcInstant"/>.</summary>
|
||||
private static string Line(string message, DateTime utcInstant, TimeSpan writerOffset)
|
||||
{
|
||||
var local = utcInstant + writerOffset;
|
||||
return $"<![LOG[{message}]LOG]!><time=\"{local:HH:mm:ss.fffffff}\" date=\"{local:M-d-yyyy}\" " +
|
||||
"component=\"X\" context=\"\" type=\"1\" thread=\"1\" file=\"\">";
|
||||
}
|
||||
|
||||
private sealed class Harness : IDisposable
|
||||
{
|
||||
private readonly TempDirectory _tmp = new TempDirectory();
|
||||
public ImeLogTracker Tracker { get; }
|
||||
public DateTime Now { get; set; } = T0;
|
||||
|
||||
public Harness(string? stateDirectory = null)
|
||||
{
|
||||
Tracker = new ImeLogTracker(
|
||||
logFolder: _tmp.Path,
|
||||
patterns: Patterns(),
|
||||
logger: new AgentLogger(_tmp.Path, AgentLogLevel.Info),
|
||||
stateDirectory: stateDirectory);
|
||||
Tracker.UtcNowProvider = () => Now;
|
||||
}
|
||||
|
||||
public string PathOf(string fileName) => Path.Combine(_tmp.Path, fileName);
|
||||
|
||||
public void Append(string fileName, string line)
|
||||
=> File.AppendAllText(PathOf(fileName), line + Environment.NewLine);
|
||||
|
||||
public Task Pass() => Tracker.CheckLogFilesAsync(CancellationToken.None);
|
||||
|
||||
public void Dispose()
|
||||
{
|
||||
Tracker.Dispose();
|
||||
_tmp.Dispose();
|
||||
}
|
||||
}
|
||||
|
||||
[Theory]
|
||||
// The writer's belief. A fresh line must resolve to the instant it was written,
|
||||
// WHATEVER that belief is — including agreement with this process (the majority case,
|
||||
// which a fix to the agent's own zone cache would have broken).
|
||||
[InlineData(2)] // CEST
|
||||
[InlineData(1)] // BST
|
||||
[InlineData(0)] // UTC
|
||||
[InlineData(-7)] // PDT — the OOBE default behind the -9 h and -17 h field cases
|
||||
[InlineData(10)] // E. Australia
|
||||
public async Task FreshLine_ResolvesToItsTrueInstant_ForAnyWriterBelief(int writerOffsetHours)
|
||||
{
|
||||
var writerOffset = TimeSpan.FromHours(writerOffsetHours);
|
||||
using var h = new Harness();
|
||||
|
||||
// First sight: backlog, must not anchor.
|
||||
h.Append("IntuneManagementExtension.log", Line("marker 1", h.Now, writerOffset));
|
||||
await h.Pass();
|
||||
|
||||
h.Now = T0.AddSeconds(10);
|
||||
var writtenAt = h.Now.AddMilliseconds(-80); // written just before the poll sees it
|
||||
h.Append("IntuneManagementExtension.log", Line("marker 2", writtenAt, writerOffset));
|
||||
await h.Pass();
|
||||
|
||||
Assert.Equal(CmTraceOffsetOrigin.LineAnchored, h.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
Assert.Equal(writtenAt, h.Tracker.LastMatchedLogTimestamp);
|
||||
Assert.Equal(writerOffsetHours * 60, h.Tracker.LastMatchedSourceOffsetMinutes);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task InterleavedEras_InOneGrowingPass_EachLineResolvesToItsOwnEra()
|
||||
{
|
||||
// The e9753578 file shape: two writer processes with different zone beliefs
|
||||
// interleaved in ONE file. Any per-file offset gets one of them wrong by 9 h;
|
||||
// per-line anchoring must get both right within the same chunk.
|
||||
var pdt = TimeSpan.FromHours(-7);
|
||||
var cest = TimeSpan.FromHours(2);
|
||||
using var h = new Harness();
|
||||
|
||||
h.Append("AgentExecutor.log", Line("marker 1", h.Now, pdt));
|
||||
await h.Pass();
|
||||
|
||||
h.Now = T0.AddSeconds(10);
|
||||
var wrotePdt = h.Now.AddMilliseconds(-90);
|
||||
var wroteCest = h.Now.AddMilliseconds(-50);
|
||||
h.Append("AgentExecutor.log", Line("marker 2", wrotePdt, pdt));
|
||||
h.Append("AgentExecutor.log", Line("marker 3", wroteCest, cest));
|
||||
|
||||
var resolved = new List<(DateTime? Ts, CmTraceOffsetOrigin Origin, int? Offset)>();
|
||||
Action<string> capture = _ => resolved.Add((
|
||||
h.Tracker.LastMatchedLogTimestamp,
|
||||
h.Tracker.LastMatchedSourceOffsetOrigin,
|
||||
h.Tracker.LastMatchedSourceOffsetMinutes));
|
||||
h.Tracker.OnPatternMatched += capture;
|
||||
try
|
||||
{
|
||||
await h.Pass();
|
||||
}
|
||||
finally
|
||||
{
|
||||
h.Tracker.OnPatternMatched -= capture;
|
||||
}
|
||||
|
||||
Assert.Equal(2, resolved.Count);
|
||||
Assert.Equal(wrotePdt, resolved[0].Ts);
|
||||
Assert.Equal(-420, resolved[0].Offset);
|
||||
Assert.Equal(wroteCest, resolved[1].Ts);
|
||||
Assert.Equal(120, resolved[1].Offset);
|
||||
Assert.All(resolved, r => Assert.Equal(CmTraceOffsetOrigin.LineAnchored, r.Origin));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task FirstSightBacklog_FallsBackToReaderZone()
|
||||
{
|
||||
using var h = new Harness();
|
||||
|
||||
h.Append("IntuneManagementExtension.log", Line("marker 1", h.Now.AddHours(-3), TimeSpan.FromHours(2)));
|
||||
await h.Pass();
|
||||
|
||||
Assert.Equal(CmTraceOffsetOrigin.None, h.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task FileFirstSeenEmpty_ItsFirstContentIsFresh()
|
||||
{
|
||||
// AgentExecutor.log in the field: the file APPEARS mid-enrollment. Seeing it empty
|
||||
// (or not existing content-wise) counts as an observation, so its very first lines
|
||||
// are provably written between passes and may anchor. This closes the warm-up gap
|
||||
// for exactly the file whose eras flip the most.
|
||||
using var h = new Harness();
|
||||
|
||||
File.WriteAllText(h.PathOf("AgentExecutor.log"), string.Empty);
|
||||
await h.Pass();
|
||||
|
||||
h.Now = T0.AddSeconds(5);
|
||||
var writtenAt = h.Now.AddMilliseconds(-60);
|
||||
h.Append("AgentExecutor.log", Line("marker 1", writtenAt, TimeSpan.FromHours(2)));
|
||||
await h.Pass();
|
||||
|
||||
Assert.Equal(CmTraceOffsetOrigin.LineAnchored, h.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
Assert.Equal(writtenAt, h.Tracker.LastMatchedLogTimestamp);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task PollGapBeyondFreshWindow_FallsBack()
|
||||
{
|
||||
// A stalled agent (GC, CPU starvation) re-polls after a long gap: the new bytes span
|
||||
// the whole gap and their age is unbounded, so the pass must not anchor — even
|
||||
// though most of its lines may in fact be recent. Conservative by design.
|
||||
using var h = new Harness();
|
||||
|
||||
h.Append("IntuneManagementExtension.log", Line("marker 1", h.Now, TimeSpan.FromHours(2)));
|
||||
await h.Pass();
|
||||
h.Now = T0.AddSeconds(10);
|
||||
h.Append("IntuneManagementExtension.log", Line("marker 2", h.Now, TimeSpan.FromHours(2)));
|
||||
await h.Pass();
|
||||
Assert.Equal(CmTraceOffsetOrigin.LineAnchored, h.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
|
||||
// Gap far beyond FreshLineMaxAge.
|
||||
h.Now = h.Now + ImeLogTracker.FreshLineMaxAge + TimeSpan.FromSeconds(10);
|
||||
h.Append("IntuneManagementExtension.log", Line("marker 3", h.Now, TimeSpan.FromHours(2)));
|
||||
await h.Pass();
|
||||
|
||||
Assert.Equal(CmTraceOffsetOrigin.None, h.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
|
||||
// And the very next tight poll is fresh again.
|
||||
h.Now = h.Now.AddSeconds(1);
|
||||
h.Append("IntuneManagementExtension.log", Line("marker 4", h.Now, TimeSpan.FromHours(2)));
|
||||
await h.Pass();
|
||||
Assert.Equal(CmTraceOffsetOrigin.LineAnchored, h.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task RestartWithRestoredBookmark_FirstPassIsBacklog_SecondPassAnchors()
|
||||
{
|
||||
// The persisted position bookmark survives a restart; the freshness guarantee must
|
||||
// not — the first pass after a restart reads the downtime backlog, whose lines can
|
||||
// be arbitrarily old.
|
||||
using var stateDir = new TempDirectory();
|
||||
using var h = new Harness(stateDirectory: stateDir.Path);
|
||||
|
||||
h.Append("IntuneManagementExtension.log", Line("marker 1", h.Now, TimeSpan.FromHours(2)));
|
||||
await h.Pass();
|
||||
h.Tracker.SaveStateForTest();
|
||||
|
||||
// "Restart": a second tracker over the same folder restores the bookmark.
|
||||
using var h2 = new HarnessOver(h, stateDir.Path);
|
||||
h2.Tracker.LoadStateForTest();
|
||||
|
||||
// Backlog written during the downtime — 30 min old, exactly on the offset grid,
|
||||
// the nastiest possible backlog shape. Must NOT anchor.
|
||||
h2.Now = T0.AddMinutes(30);
|
||||
h2.Append(Line("marker 2", T0.AddSeconds(20), TimeSpan.FromHours(2)));
|
||||
await h2.Pass();
|
||||
Assert.Equal(CmTraceOffsetOrigin.None, h2.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
|
||||
// The next tight poll is fresh again.
|
||||
h2.Now = h2.Now.AddSeconds(1);
|
||||
var writtenAt = h2.Now.AddMilliseconds(-70);
|
||||
h2.Append(Line("marker 3", writtenAt, TimeSpan.FromHours(2)));
|
||||
await h2.Pass();
|
||||
Assert.Equal(CmTraceOffsetOrigin.LineAnchored, h2.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
Assert.Equal(writtenAt, h2.Tracker.LastMatchedLogTimestamp);
|
||||
}
|
||||
|
||||
/// <summary>Second tracker over the FIRST harness's log folder — the "restarted agent".</summary>
|
||||
private sealed class HarnessOver : IDisposable
|
||||
{
|
||||
private readonly string _logFolder;
|
||||
public ImeLogTracker Tracker { get; }
|
||||
public DateTime Now { get; set; }
|
||||
|
||||
public HarnessOver(Harness original, string stateDirectory)
|
||||
{
|
||||
_logFolder = Path.GetDirectoryName(original.PathOf("x"));
|
||||
Tracker = new ImeLogTracker(
|
||||
logFolder: _logFolder,
|
||||
patterns: Patterns(),
|
||||
logger: new AgentLogger(_logFolder, AgentLogLevel.Info),
|
||||
stateDirectory: stateDirectory);
|
||||
Tracker.UtcNowProvider = () => Now;
|
||||
}
|
||||
|
||||
public void Append(string line)
|
||||
=> File.AppendAllText(Path.Combine(_logFolder, "IntuneManagementExtension.log"), line + Environment.NewLine);
|
||||
|
||||
public Task Pass() => Tracker.CheckLogFilesAsync(CancellationToken.None);
|
||||
|
||||
public void Dispose() => Tracker.Dispose();
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task FreshlyWrittenReplayLine_OnExactGridAge_ResolvesToRoughlyNow()
|
||||
{
|
||||
// Characterization of the one accepted edge: a line freshly WRITTEN but carrying a
|
||||
// REPLAYED timestamp whose age is exactly a grid multiple (here 30 min) measures
|
||||
// that age as an "offset" and resolves to ~now instead of its replayed past. The
|
||||
// error is bounded by construction (an anchored line always lands at now ± 2 min),
|
||||
// and sub-24h replays are treated as current by the historic-replay guard anyway.
|
||||
using var h = new Harness();
|
||||
|
||||
h.Append("IntuneManagementExtension.log", Line("marker 1", h.Now, TimeSpan.Zero));
|
||||
await h.Pass();
|
||||
|
||||
h.Now = T0.AddSeconds(10);
|
||||
var replayedInstant = h.Now.AddMinutes(-30);
|
||||
h.Append("IntuneManagementExtension.log", Line("marker 2", replayedInstant, TimeSpan.Zero));
|
||||
await h.Pass();
|
||||
|
||||
Assert.Equal(CmTraceOffsetOrigin.LineAnchored, h.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
Assert.NotNull(h.Tracker.LastMatchedLogTimestamp);
|
||||
var error = (h.Tracker.LastMatchedLogTimestamp!.Value - h.Now).Duration();
|
||||
Assert.True(error <= CmTraceOffsetCalibrator.MaxGridResidual,
|
||||
$"anchored line must resolve to now ± residual, was off by {error}");
|
||||
}
|
||||
|
||||
// =====================================================================
|
||||
// The committed field fixture — session e9753578, ImeLogs/AgentExecutor.log.
|
||||
// One file, two writer eras (PDT hour-05 / CEST hour-14), interleaved, flipping
|
||||
// BOTH ways. Replayed here as the live tail the field agent saw: entry by entry,
|
||||
// with the clock following the true write time.
|
||||
// =====================================================================
|
||||
|
||||
private static string FixturePath()
|
||||
{
|
||||
var dir = AppContext.BaseDirectory;
|
||||
for (int i = 0; i < 12; i++)
|
||||
{
|
||||
if (File.Exists(Path.Combine(dir, "AutopilotMonitor.sln")))
|
||||
return Path.Combine(dir, "tests", "fixtures", "cmtrace-logs",
|
||||
"agentexecutor-two-writer-eras-v1.cmtrace");
|
||||
var parent = Directory.GetParent(dir)?.FullName;
|
||||
if (parent == null || parent == dir) break;
|
||||
dir = parent;
|
||||
}
|
||||
throw new DirectoryNotFoundException(
|
||||
"Could not locate repo root (AutopilotMonitor.sln) walking up from " + AppContext.BaseDirectory);
|
||||
}
|
||||
|
||||
/// <summary>Group the fixture's physical lines into complete CMTrace entries (multiline-safe).</summary>
|
||||
private static List<string> FixtureEntries()
|
||||
{
|
||||
var entries = new List<string>();
|
||||
string? pending = null;
|
||||
foreach (var rawWithBom in File.ReadAllLines(FixturePath()))
|
||||
{
|
||||
// The fixture keeps the original file's BOM verbatim — it sat at the START of
|
||||
// the real AgentExecutor.log, which is mid-file in this excerpt.
|
||||
var raw = rawWithBom.TrimStart('');
|
||||
if (pending == null)
|
||||
{
|
||||
if (raw.Length == 0 || raw[0] == '#') continue;
|
||||
if (!raw.StartsWith("<![LOG[", StringComparison.Ordinal)) continue;
|
||||
if (raw.Contains("]LOG]!>")) { entries.Add(raw); continue; }
|
||||
pending = raw;
|
||||
}
|
||||
else
|
||||
{
|
||||
pending += "\n" + raw;
|
||||
if (raw.Contains("]LOG]!>")) { entries.Add(pending!); pending = null; }
|
||||
}
|
||||
}
|
||||
return entries;
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task TwoWriterEraFixture_EveryLineOfBothErasResolvesToItsTrueInstant()
|
||||
{
|
||||
// The committed fixture is a curated, verbatim excerpt of the transition window
|
||||
// (commit policy: anonymized, versioned) — 20 entries covering both eras and the flip.
|
||||
var entries = FixtureEntries();
|
||||
Assert.True(entries.Count >= 15, $"fixture unexpectedly small: {entries.Count} entries");
|
||||
|
||||
using var h = new Harness();
|
||||
|
||||
// Match every fixture entry.
|
||||
h.Tracker.CompilePatterns(new List<ImeLogPattern>
|
||||
{
|
||||
new ImeLogPattern
|
||||
{
|
||||
PatternId = "T-ANY", Category = "always", Enabled = true,
|
||||
Pattern = ".+", Action = "noop",
|
||||
Parameters = new Dictionary<string, string>(),
|
||||
},
|
||||
});
|
||||
|
||||
// The file exists (empty) before its first content — first sight is the observation
|
||||
// baseline, everything after is a fresh tail, exactly like the field.
|
||||
File.WriteAllText(h.PathOf("AgentExecutor.log"), string.Empty);
|
||||
h.Now = new DateTime(2026, 8, 20, 12, 13, 30, DateTimeKind.Utc);
|
||||
await h.Pass();
|
||||
|
||||
var anchored = 0;
|
||||
var resolvedList = new List<(DateTime Resolved, DateTime Expected)>();
|
||||
Action<string> capture = _ =>
|
||||
{
|
||||
if (h.Tracker.LastMatchedSourceOffsetOrigin == CmTraceOffsetOrigin.LineAnchored)
|
||||
anchored++;
|
||||
if (h.Tracker.LastMatchedLogTimestamp.HasValue && _expectedForCurrentEntry.HasValue)
|
||||
resolvedList.Add((h.Tracker.LastMatchedLogTimestamp.Value, _expectedForCurrentEntry.Value));
|
||||
};
|
||||
h.Tracker.OnPatternMatched += capture;
|
||||
try
|
||||
{
|
||||
foreach (var entry in entries)
|
||||
{
|
||||
CmTraceLogEntry? parsed;
|
||||
Assert.True(CmTraceLogParser.TryParseLine(entry, out parsed), "fixture entry did not parse");
|
||||
|
||||
// Era by local hour: the fixture holds exactly two eras — PDT (UTC-7) lines
|
||||
// render at local hour 05, CEST (UTC+2) lines at hour 14 (fixture header).
|
||||
var eraOffset = parsed.LocalTimestamp.Hour == 14
|
||||
? TimeSpan.FromHours(2)
|
||||
: TimeSpan.FromHours(-7);
|
||||
var trueUtc = DateTime.SpecifyKind(parsed.LocalTimestamp - eraOffset, DateTimeKind.Utc);
|
||||
|
||||
// The clock follows the write; never move backwards (interleaved eras are
|
||||
// written in true-UTC order, but guard against sub-ms jitter).
|
||||
var readAt = trueUtc.AddMilliseconds(120);
|
||||
if (readAt > h.Now) h.Now = readAt;
|
||||
|
||||
// In production the 100 ms poll keeps running through write silences — every
|
||||
// empty look refreshes the freshness window. The fixture's transition window
|
||||
// spans multi-minute write gaps, so replay that cadence with one empty poll
|
||||
// just before each append; without it the NEXT pass would (correctly!)
|
||||
// classify the gap as a stall and refuse to anchor.
|
||||
h.Now = h.Now.AddMilliseconds(-100);
|
||||
await h.Pass();
|
||||
h.Now = readAt;
|
||||
|
||||
_expectedForCurrentEntry = trueUtc;
|
||||
File.AppendAllText(h.PathOf("AgentExecutor.log"), entry + Environment.NewLine);
|
||||
await h.Pass();
|
||||
_expectedForCurrentEntry = null;
|
||||
}
|
||||
}
|
||||
finally
|
||||
{
|
||||
h.Tracker.OnPatternMatched -= capture;
|
||||
}
|
||||
|
||||
// Every matched entry resolved to the instant its writer rendered — across BOTH
|
||||
// eras, including the flips. This is the exact property whose absence produced the
|
||||
// -9 h script durations.
|
||||
Assert.Equal(entries.Count, resolvedList.Count);
|
||||
Assert.All(resolvedList, r => Assert.Equal(r.Expected, r.Resolved));
|
||||
Assert.True(anchored == resolvedList.Count,
|
||||
$"expected every entry line-anchored, got {anchored}/{resolvedList.Count}");
|
||||
|
||||
// Both eras genuinely exercised: PDT entries render at local hour 05, CEST at 14.
|
||||
Assert.Contains(resolvedList, r => (r.Expected + TimeSpan.FromHours(-7)).Hour == 5);
|
||||
Assert.Contains(resolvedList, r => (r.Expected + TimeSpan.FromHours(2)).Hour == 14);
|
||||
}
|
||||
|
||||
private DateTime? _expectedForCurrentEntry;
|
||||
}
|
||||
}
|
||||
+36
-33
@@ -80,36 +80,33 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
}
|
||||
|
||||
[Theory]
|
||||
// The writer's belief. Whatever it is, a line written at T must come back as T.
|
||||
[InlineData(2)] // CEST — the bfff9b1c writer, while the agent still believed BST
|
||||
[InlineData(1)] // BST — writer and a UK-defaulted agent agreeing
|
||||
[InlineData(-7)] // PDT — the OOBE default behind the -17 h sessions
|
||||
// The writer's belief. The MEASUREMENT must recover it exactly, whatever it is.
|
||||
[InlineData(2)] // CEST
|
||||
[InlineData(1)] // BST
|
||||
[InlineData(-7)] // PDT — the OOBE default behind the -17 h and -9 h field cases
|
||||
[InlineData(10)] // E. Australia
|
||||
[InlineData(0)] // UTC
|
||||
public async Task ResolvesLineToTheInstantItWasWritten_ForAnyWriterBelief(int writerOffsetHours)
|
||||
public async Task MeasuresTheWritersOffsetExactly_ForAnyBelief(int writerOffsetHours)
|
||||
{
|
||||
// NOTE: the per-FILE measurement asserted here is OBSERVATIONAL — its application was
|
||||
// reverted on 2026-08-20 (04b1a7c6) because one offset per file is wrong when a file
|
||||
// holds interleaved writer eras. Resolution now anchors per LINE instead (see
|
||||
// ImeLogTrackerLineAnchoringTests, which restores the "a line written at T resolves
|
||||
// to T" property era-safely). The per-file measurement stays for the Info log and
|
||||
// measuredWriterOffsetMinutes provenance.
|
||||
var writerOffset = TimeSpan.FromHours(writerOffsetHours);
|
||||
using var h = new Harness();
|
||||
|
||||
// Pass 1 — first sight of the file. Its content may be arbitrarily old, so nothing is
|
||||
// calibrated from it.
|
||||
h.Append(Line("marker 1", h.Now, writerOffset));
|
||||
await h.Pass();
|
||||
|
||||
// Pass 2 — the file has grown against a size we already observed, so this line was
|
||||
// written within a poll interval and is a valid anchor.
|
||||
h.Now = T0.AddSeconds(10);
|
||||
h.Append(Line("marker 2", h.Now, writerOffset));
|
||||
await h.Pass();
|
||||
|
||||
// Pass 3 — resolved with the measured offset.
|
||||
h.Now = T0.AddSeconds(20);
|
||||
var writtenAt = h.Now;
|
||||
h.Append(Line("marker 3", writtenAt, writerOffset));
|
||||
await h.Pass();
|
||||
|
||||
Assert.True(h.Tracker.LastMatchedLogTimestamp.HasValue);
|
||||
Assert.Equal(writtenAt, h.Tracker.LastMatchedLogTimestamp.Value);
|
||||
TimeSpan measured;
|
||||
Assert.True(h.Tracker.OffsetCalibrator.TryGetOffset(LogFileName, out measured));
|
||||
Assert.Equal(writerOffset, measured);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
@@ -175,8 +172,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
TimeSpan after;
|
||||
Assert.True(h.Tracker.OffsetCalibrator.TryGetOffset(LogFileName, out after));
|
||||
Assert.Equal(TimeSpan.FromHours(2), after);
|
||||
Assert.True(h.Tracker.LastMatchedLogTimestamp.HasValue);
|
||||
Assert.Equal(writtenAt, h.Tracker.LastMatchedLogTimestamp.Value);
|
||||
// The measurement follows the restart. Applying it is what the 2026-08-20 revert
|
||||
// removed — that is exactly the case a file with two writer eras breaks.
|
||||
Assert.Equal(120, h.Tracker.LastMatchedMeasuredWriterOffsetMinutes);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
@@ -204,12 +202,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task RecordsProvenance_ForACalibratedLine()
|
||||
public async Task RecordsMeasuredOffsetSeparatelyFromTheAppliedOne()
|
||||
{
|
||||
// P8: what the writer wrote, what we subtracted, and how we knew — the evidence that
|
||||
// makes a stored timestamp recomputable without the diagnostics archive.
|
||||
// The regression that forced the revert shipped an event tagged "calibrated" while
|
||||
// carrying an offset that did not hold for that line. Measured and applied are now
|
||||
// separate fields so a future reader cannot mistake one for the other.
|
||||
using var h = new Harness();
|
||||
var writerOffset = TimeSpan.FromHours(-7); // PST/PDT, the OOBE default
|
||||
var writerOffset = TimeSpan.FromHours(-7); // PDT, the OOBE default
|
||||
|
||||
h.Append(Line("marker 1", h.Now, writerOffset));
|
||||
await h.Pass();
|
||||
@@ -219,18 +218,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
await h.Pass();
|
||||
|
||||
h.Now = T0.AddSeconds(20);
|
||||
var writtenAt = h.Now;
|
||||
h.Append(Line("marker 3", writtenAt, writerOffset));
|
||||
h.Append(Line("marker 3", h.Now, writerOffset));
|
||||
await h.Pass();
|
||||
|
||||
Assert.Equal(CmTraceOffsetOrigin.Calibrated, h.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
Assert.Equal(-420, h.Tracker.LastMatchedSourceOffsetMinutes);
|
||||
Assert.True(h.Tracker.LastMatchedSourceLocalTimestamp.HasValue);
|
||||
// Measured: the writer's actual belief, per file.
|
||||
Assert.Equal(-420, h.Tracker.LastMatchedMeasuredWriterOffsetMinutes);
|
||||
|
||||
// The raw local value is kept verbatim, with no zone attached — attaching one would
|
||||
// re-introduce exactly the assumption this change removes.
|
||||
Assert.Equal(writtenAt + writerOffset, h.Tracker.LastMatchedSourceLocalTimestamp.Value);
|
||||
Assert.Equal(DateTimeKind.Unspecified, h.Tracker.LastMatchedSourceLocalTimestamp.Value.Kind);
|
||||
// Applied: the line's OWN anchor (fresh pass), never the per-file "calibrated" value —
|
||||
// the two must stay distinguishable even when they agree numerically.
|
||||
Assert.Equal(CmTraceOffsetOrigin.LineAnchored, h.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
Assert.NotEqual(CmTraceOffsetOrigin.Calibrated, h.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
@@ -244,8 +241,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
await h.Pass();
|
||||
|
||||
Assert.Equal(CmTraceOffsetOrigin.None, h.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
Assert.Null(h.Tracker.LastMatchedSourceOffsetMinutes);
|
||||
Assert.True(h.Tracker.LastMatchedSourceLocalTimestamp.HasValue);
|
||||
|
||||
// The APPLIED offset is reported even on the fallback path — an event that states no
|
||||
// offset at all cannot be recomputed later, which defeats the purpose of recording
|
||||
// provenance. Asserted against the running machine's zone so this stays portable.
|
||||
var readerZone = (int)TimeZoneInfo.Local
|
||||
.GetUtcOffset(h.Tracker.LastMatchedSourceLocalTimestamp!.Value).TotalMinutes;
|
||||
Assert.Equal(readerZone, h.Tracker.LastMatchedSourceOffsetMinutes);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
|
||||
+25
@@ -107,6 +107,31 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Transport
|
||||
Assert.False(req.Headers.ContainsKey("X-Bootstrap-Token"));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task UploadBatchAsync_stamps_send_time_header_per_attempt()
|
||||
{
|
||||
// P14: X-Send-Time-Utc carries the device clock at the SEND moment, round-trip
|
||||
// ISO-8601, one value per request. A retry is a new send moment — the header is
|
||||
// stamped inside UploadBatchAsync, so each attempt gets a fresh value.
|
||||
using var rig = new Rig();
|
||||
rig.Handler.QueueStatus(HttpStatusCode.ServiceUnavailable);
|
||||
rig.Handler.QueueStatus(HttpStatusCode.OK);
|
||||
|
||||
var before = DateTime.UtcNow;
|
||||
await rig.Sut.UploadBatchAsync(new[] { NewEventItem(1) }, CancellationToken.None);
|
||||
await rig.Sut.UploadBatchAsync(new[] { NewEventItem(1) }, CancellationToken.None);
|
||||
var after = DateTime.UtcNow;
|
||||
|
||||
Assert.Equal(2, rig.Handler.Captured.Count);
|
||||
foreach (var req in rig.Handler.Captured)
|
||||
{
|
||||
Assert.True(req.TryGetHeader("X-Send-Time-Utc", out var raw));
|
||||
var parsed = DateTime.Parse(raw, null, System.Globalization.DateTimeStyles.RoundtripKind);
|
||||
Assert.Equal(DateTimeKind.Utc, parsed.Kind);
|
||||
Assert.InRange(parsed, before.AddSeconds(-1), after.AddSeconds(1));
|
||||
}
|
||||
}
|
||||
|
||||
// ============================================================ Compression (bandwidth)
|
||||
|
||||
[Fact]
|
||||
|
||||
+47
-7
@@ -12,8 +12,21 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// <summary>The writer declared its offset in the line ("+480"). Authoritative.</summary>
|
||||
Bias = 1,
|
||||
|
||||
/// <summary>Offset measured from a freshly appended line. See <see cref="CmTraceOffsetCalibrator"/>.</summary>
|
||||
/// <summary>
|
||||
/// A per-FILE measured offset was applied. Retired by the 2026-08-20 revert (04b1a7c6):
|
||||
/// one offset per file is wrong when a file holds lines from two writer eras. Kept so
|
||||
/// stored events from agent 2.0.1410 remain interpretable.
|
||||
/// </summary>
|
||||
Calibrated = 2,
|
||||
|
||||
/// <summary>
|
||||
/// The line anchored ITSELF: it was read in a pass whose lines are provably fresh
|
||||
/// (written since the previous poll), so its own distance to the agent clock, rounded
|
||||
/// to the 15-minute offset grid, IS the writer's offset — no cross-line state involved.
|
||||
/// Immune to interleaved writer eras by construction. See
|
||||
/// <see cref="CmTraceOffsetCalibrator.TryMeasureOffset"/>.
|
||||
/// </summary>
|
||||
LineAnchored = 3,
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
@@ -98,24 +111,51 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// <param name="localTimestamp">The line's local time exactly as written (Kind is ignored).</param>
|
||||
/// <param name="agentUtcNow">The agent's UTC clock at parse time.</param>
|
||||
/// <returns><c>true</c> when the anchor was accepted and the offset updated.</returns>
|
||||
public bool TryCalibrate(string sourceKey, DateTime localTimestamp, DateTime agentUtcNow)
|
||||
/// <summary>
|
||||
/// The pure measurement: the distance between a FRESH line's local time and the agent's
|
||||
/// UTC clock, rounded to the 15-minute offset grid, is the writer's UTC offset.
|
||||
/// <para>
|
||||
/// Freshness is the caller's obligation and is what makes this correct — for a line
|
||||
/// written within the last poll interval, <c>local - now</c> differs from the writer's
|
||||
/// true offset only by seconds, which the grid rounding absorbs. Returns <c>false</c>
|
||||
/// when the residual exceeds <see cref="MaxGridResidual"/> (the line is not fresh, or
|
||||
/// the writer's clock is broken) or the rounded value is not a real timezone offset.
|
||||
/// </para>
|
||||
/// <para>
|
||||
/// Known, accepted edge: a freshly WRITTEN line carrying an old REPLAYED timestamp whose
|
||||
/// age happens to sit within the residual of an exact grid multiple measures that age as
|
||||
/// an "offset" — the line then resolves to roughly the read time instead of its replayed
|
||||
/// past. The error is bounded by construction (an anchored line always resolves to
|
||||
/// now ± <see cref="MaxGridResidual"/>), the case needs an age of exactly N×15 min ± 2 min,
|
||||
/// and sub-24h replays are treated as current by the historic-replay guard anyway.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public static bool TryMeasureOffset(DateTime localTimestamp, DateTime agentUtcNow, out TimeSpan offset)
|
||||
{
|
||||
if (string.IsNullOrEmpty(sourceKey)) return false;
|
||||
|
||||
var candidate = DateTime.SpecifyKind(localTimestamp, DateTimeKind.Unspecified)
|
||||
- DateTime.SpecifyKind(agentUtcNow, DateTimeKind.Unspecified);
|
||||
|
||||
var gridUnits = Math.Round(candidate.TotalMinutes / OffsetGrid.TotalMinutes,
|
||||
MidpointRounding.AwayFromZero);
|
||||
var offset = TimeSpan.FromMinutes(gridUnits * OffsetGrid.TotalMinutes);
|
||||
offset = TimeSpan.FromMinutes(gridUnits * OffsetGrid.TotalMinutes);
|
||||
|
||||
// Off-grid by more than the tolerance: the anchor was not fresh, or the writer's own
|
||||
// clock is broken. Either way it must not become the offset.
|
||||
// Off-grid by more than the tolerance: the line was not fresh, or the writer's own
|
||||
// clock is broken. Either way it must not become an offset.
|
||||
if ((candidate - offset).Duration() > MaxGridResidual) return false;
|
||||
|
||||
// Not a value any real timezone can produce.
|
||||
if (offset < MinOffset || offset > MaxOffset) return false;
|
||||
|
||||
return true;
|
||||
}
|
||||
|
||||
public bool TryCalibrate(string sourceKey, DateTime localTimestamp, DateTime agentUtcNow)
|
||||
{
|
||||
if (string.IsNullOrEmpty(sourceKey)) return false;
|
||||
|
||||
TimeSpan offset;
|
||||
if (!TryMeasureOffset(localTimestamp, agentUtcNow, out offset)) return false;
|
||||
|
||||
lock (_lock)
|
||||
{
|
||||
if (_bySource.TryGetValue(sourceKey, out var existing))
|
||||
|
||||
+99
-19
@@ -77,12 +77,21 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
var fileInfo = new FileInfo(filePath);
|
||||
if (!fileInfo.Exists) continue;
|
||||
|
||||
// Captured BEFORE GetSafePosition, which creates the entry as a side effect.
|
||||
// Growth measured against a previously observed size is what makes the last
|
||||
// line of this pass a valid "written now" calibration anchor.
|
||||
// Captured BEFORE MarkChecked below stamps this pass. Growth measured
|
||||
// against a previously observed state is what makes this pass's lines valid
|
||||
// "written now" anchors — for the per-file measurement AND per-line anchoring.
|
||||
var hadPreviousObservation = _positionTracker.HasSeen(filePath);
|
||||
var lastCheckedUtc = _positionTracker.GetLastCheckedUtc(filePath);
|
||||
var passNowUtc = UtcNowProvider();
|
||||
|
||||
var startPos = _positionTracker.GetSafePosition(filePath, fileInfo.Length);
|
||||
|
||||
// Every look counts, including "no new data" and an empty first sight: the
|
||||
// NEXT pass's freshness window is measured from here. Restored bookmarks
|
||||
// deliberately carry no LastCheckedUtc — the first pass after a restart reads
|
||||
// downtime backlog and must never count as fresh.
|
||||
_positionTracker.MarkChecked(filePath, passNowUtc);
|
||||
|
||||
if (startPos >= fileInfo.Length)
|
||||
{
|
||||
// M2: guard the interpolated string so it isn't built every 100 ms tick
|
||||
@@ -95,6 +104,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
_logger.Trace($"ImeLogTracker: reading {Path.GetFileName(filePath)} from pos {startPos} (size={fileInfo.Length}, delta={fileInfo.Length - startPos})");
|
||||
|
||||
_currentSourceFileName = Path.GetFileName(filePath);
|
||||
_currentPassLinesAreFresh = hadPreviousObservation
|
||||
&& lastCheckedUtc > DateTime.MinValue
|
||||
&& (passNowUtc - lastCheckedUtc) <= FreshLineMaxAge;
|
||||
|
||||
// Newest bias-less line of this pass — the calibration anchor. Bias-carrying
|
||||
// lines are skipped: they already state the writer's offset, so they need no
|
||||
@@ -210,7 +222,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// growing pass, during which lines fall back to the reader zone and are
|
||||
// flagged as such.
|
||||
if (hadPreviousObservation && calibrationAnchor != null)
|
||||
CalibrateFrom(_currentSourceFileName, calibrationAnchor);
|
||||
CalibrateFrom(_currentSourceFileName, Path.GetFileName(filePath), calibrationAnchor);
|
||||
}
|
||||
}
|
||||
catch (FileNotFoundException) { }
|
||||
@@ -254,6 +266,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
LastMatchedSourceLocalTimestamp = null;
|
||||
LastMatchedSourceOffsetMinutes = null;
|
||||
LastMatchedSourceOffsetOrigin = CmTraceOffsetOrigin.None;
|
||||
LastMatchedMeasuredWriterOffsetMinutes = null;
|
||||
}
|
||||
else
|
||||
{
|
||||
@@ -263,6 +276,15 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
LastMatchedSourceLocalTimestamp = entry.HasTimestamp ? entry.LocalTimestamp : (DateTime?)null;
|
||||
LastMatchedSourceOffsetMinutes = offsetMinutes;
|
||||
LastMatchedSourceOffsetOrigin = origin;
|
||||
|
||||
// Observational: what the calibrator measured for this file, distinct from what
|
||||
// was applied above.
|
||||
TimeSpan measuredWriterOffset;
|
||||
LastMatchedMeasuredWriterOffsetMinutes =
|
||||
_currentSourceFileName != null
|
||||
&& OffsetCalibrator.TryGetOffset(_currentSourceFileName, out measuredWriterOffset)
|
||||
? (int)measuredWriterOffset.TotalMinutes
|
||||
: (int?)null;
|
||||
}
|
||||
|
||||
// Generic pattern-match hook (M4.4.4). Invoked before action-specific callbacks so
|
||||
@@ -640,52 +662,110 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
|
||||
if (!entry.HasTimestamp) return UtcNowProvider();
|
||||
|
||||
// Measured offset of the process that wrote this file.
|
||||
TimeSpan measured;
|
||||
DateTime calibrated;
|
||||
if (_currentSourceFileName != null
|
||||
&& OffsetCalibrator.TryGetOffset(_currentSourceFileName, out measured)
|
||||
&& OffsetCalibrator.TryResolveUtc(_currentSourceFileName, entry.LocalTimestamp, out calibrated))
|
||||
// ERA-AWARE RESOLUTION (2026-08-20, second attempt): a FRESH line anchors ITSELF.
|
||||
//
|
||||
// The first attempt (e9dba11b, reverted in 04b1a7c6) applied one measured offset per
|
||||
// FILE — wrong, because a single log file holds lines from multiple writer eras:
|
||||
// AgentExecutor.log is written by short-lived child processes whose zone belief
|
||||
// flips per process, interleaved in one file (fixture
|
||||
// tests/fixtures/cmtrace-logs/agentexecutor-two-writer-eras-v1.cmtrace). Any
|
||||
// cross-line anchor — per file, or nearest-in-write-order — inherits that trap.
|
||||
//
|
||||
// Per-line self-anchoring does not: at a 100 ms poll every line of a growing pass
|
||||
// was written essentially "now", so its own distance to the agent clock IS its
|
||||
// writer's offset, era by era. The line's timestamp still contributes the sub-poll
|
||||
// precision and ordering (two lines 6 ms apart stay 6 ms apart — a plain
|
||||
// occurredAt=now could not do that), while the offset grid absorbs poll latency.
|
||||
// Freshness is load-bearing (see FreshLineMaxAge) — backlog passes, restart
|
||||
// catch-up and replay logs must never anchor, because an old line's AGE can round
|
||||
// onto the grid.
|
||||
if (_currentPassLinesAreFresh)
|
||||
{
|
||||
origin = CmTraceOffsetOrigin.Calibrated;
|
||||
offsetMinutes = (int)measured.TotalMinutes;
|
||||
return calibrated;
|
||||
TimeSpan lineOffset;
|
||||
if (CmTraceOffsetCalibrator.TryMeasureOffset(entry.LocalTimestamp, UtcNowProvider(), out lineOffset))
|
||||
{
|
||||
origin = CmTraceOffsetOrigin.LineAnchored;
|
||||
offsetMinutes = (int)lineOffset.TotalMinutes;
|
||||
return DateTime.SpecifyKind(entry.LocalTimestamp - lineOffset, DateTimeKind.Utc);
|
||||
}
|
||||
}
|
||||
|
||||
// Not calibrated yet (first growing pass, or a file that never grows while we watch).
|
||||
// Falls back to this process's zone, which is right only if the writer happens to
|
||||
// share our belief. Origin stays None so the emitted event says so.
|
||||
// Fallback for everything not provably fresh: assume the reader's zone, UNIFORMLY.
|
||||
// Wrong in absolute terms whenever the writer held a different belief, but
|
||||
// self-consistent — both ends of a duration are wrong by the same amount, so derived
|
||||
// durations stay right. That asymmetry is the lesson of the 04b1a7c6 revert:
|
||||
// partially corrected is strictly worse than uniformly wrong. Origin stays None so
|
||||
// the emitted event says so.
|
||||
var readerZoneOffset = TimeZoneInfo.Local.GetUtcOffset(entry.LocalTimestamp);
|
||||
offsetMinutes = (int)readerZoneOffset.TotalMinutes;
|
||||
return CmTraceLogParser.ResolveUtcAssumingReaderZone(entry.LocalTimestamp);
|
||||
}
|
||||
|
||||
// Field-forensics (tripwire, 2026-08-20): sessions e9753578 and 067797d8 both logged a
|
||||
// measurement whose LABEL and ANCHOR could not have come from the same file iteration —
|
||||
// 067797d8's anchor value (19:51:26.948) does not even exist in ANY log file on the
|
||||
// device, and IntuneManagementExtension.log never produced its expected first
|
||||
// measurement at all. Mechanism unexplained; resolution is immune (per-line anchoring),
|
||||
// but the observational layer must convict the culprit on the next occurrence. Hence:
|
||||
// the stream's file name travels alongside the label (a mismatch is THE smoking gun),
|
||||
// and the first rejected anchor per file becomes visible instead of silent.
|
||||
private readonly HashSet<string> _calibrationRejectLogged = new HashSet<string>(StringComparer.OrdinalIgnoreCase);
|
||||
|
||||
/// <summary>
|
||||
/// Feed the pass's newest bias-less line to the calibrator and report a measured offset
|
||||
/// that disagrees with this process's own zone — that disagreement is precisely the
|
||||
/// condition that used to corrupt every IME-derived timestamp silently.
|
||||
/// </summary>
|
||||
private void CalibrateFrom(string sourceFileName, CmTraceLogEntry anchor)
|
||||
/// <param name="sourceFileName">The calibration key (<c>_currentSourceFileName</c>).</param>
|
||||
/// <param name="streamFileName">The file the enclosing iteration actually read. Must equal
|
||||
/// <paramref name="sourceFileName"/> — logged loudly when it does not (see tripwire note).</param>
|
||||
private void CalibrateFrom(string sourceFileName, string streamFileName, CmTraceLogEntry anchor)
|
||||
{
|
||||
if (!string.Equals(sourceFileName, streamFileName, StringComparison.OrdinalIgnoreCase))
|
||||
{
|
||||
_logger?.Warning(
|
||||
$"ImeLogTracker: CALIBRATION LABEL MISMATCH — key='{sourceFileName}' but the iteration read '{streamFileName}' " +
|
||||
$"(anchor local={anchor.LocalTimestamp:yyyy-MM-ddTHH:mm:ss.fffffff}). Skipping this anchor; see tripwire note.");
|
||||
return;
|
||||
}
|
||||
|
||||
TimeSpan previous;
|
||||
var hadOffset = OffsetCalibrator.TryGetOffset(sourceFileName, out previous);
|
||||
|
||||
if (!OffsetCalibrator.TryCalibrate(sourceFileName, anchor.LocalTimestamp, UtcNowProvider()))
|
||||
{
|
||||
// Once per file: why a file that visibly grows never produces a measurement.
|
||||
// 067797d8 ran 24 s of growing IME.log passes with no measurement at all — this
|
||||
// silence is exactly what made the phenomenon undiagnosable from the log.
|
||||
if (_calibrationRejectLogged.Add(sourceFileName))
|
||||
{
|
||||
_logger?.Debug(
|
||||
$"ImeLogTracker: {sourceFileName} anchor rejected by calibrator " +
|
||||
$"(anchor local={anchor.LocalTimestamp:yyyy-MM-ddTHH:mm:ss.fffffff}, now={UtcNowProvider():HH:mm:ss.fff}Z) — first rejection for this file, further ones stay silent.");
|
||||
}
|
||||
return;
|
||||
}
|
||||
|
||||
TimeSpan measured;
|
||||
if (!OffsetCalibrator.TryGetOffset(sourceFileName, out measured)) return;
|
||||
if (hadOffset && measured == previous) return;
|
||||
|
||||
// The anchor's local timestamp is part of the record ON PURPOSE (tripwire, 2026-08-20):
|
||||
// session e9753578 logged "+02:00 measured for IntuneManagementExtension.log" although
|
||||
// that file provably held no +2-era line — an anchor/label pairing the committed code
|
||||
// could not be shown to produce. Should it ever happen again, the logged anchor value
|
||||
// itself will prove (or refute) the crossing without needing the device's log files.
|
||||
var readerZoneOffset = TimeZoneInfo.Local.GetUtcOffset(UtcNowProvider());
|
||||
if (measured == readerZoneOffset)
|
||||
{
|
||||
_logger?.Debug(
|
||||
$"ImeLogTracker: {sourceFileName} writer offset measured {measured} (matches this process).");
|
||||
$"ImeLogTracker: {sourceFileName} writer offset measured {measured} (matches this process, anchor local={anchor.LocalTimestamp:yyyy-MM-ddTHH:mm:ss.fff}).");
|
||||
return;
|
||||
}
|
||||
|
||||
_logger?.Info(
|
||||
$"ImeLogTracker: {sourceFileName} writer offset measured {measured}, this process believes {readerZoneOffset} " +
|
||||
$"— timestamps from this file are corrected by {(measured - readerZoneOffset).Negate()}.");
|
||||
$"(anchor local={anchor.LocalTimestamp:yyyy-MM-ddTHH:mm:ss.fff}). Measurement is observational — resolution anchors per line.");
|
||||
}
|
||||
|
||||
}
|
||||
|
||||
@@ -103,6 +103,24 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// </summary>
|
||||
private string _currentSourceFileName;
|
||||
|
||||
/// <summary>
|
||||
/// Whether every line of the file iteration currently in flight is provably FRESH —
|
||||
/// written after the previous look at this file, which happened at most
|
||||
/// <see cref="FreshLineMaxAge"/> ago in THIS process. Only then may a line anchor its
|
||||
/// own UTC offset (<see cref="CmTraceOffsetCalibrator.TryMeasureOffset"/>): the grid
|
||||
/// rounding is safe when the line's age is bounded by seconds, and becomes a trap on
|
||||
/// backlog whose age can hit an exact grid multiple. Same single-task justification as
|
||||
/// <see cref="_currentSourceFileName"/>.
|
||||
/// </summary>
|
||||
private bool _currentPassLinesAreFresh;
|
||||
|
||||
/// <summary>
|
||||
/// Maximum gap between two looks at a file for its new bytes to count as fresh. Far
|
||||
/// above the 100 ms poll (rides out GC pauses and ESP CPU starvation), far below the
|
||||
/// 13-minute danger zone where a line's AGE could round onto the 15-minute offset grid.
|
||||
/// </summary>
|
||||
internal static readonly TimeSpan FreshLineMaxAge = TimeSpan.FromSeconds(30);
|
||||
|
||||
internal static DateTime NormalizeUtc(DateTime value) =>
|
||||
value.Kind == DateTimeKind.Utc ? value : DateTime.SpecifyKind(value, DateTimeKind.Utc);
|
||||
|
||||
@@ -228,6 +246,19 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// <summary>How that offset was arrived at — declared, measured, or neither.</summary>
|
||||
public CmTraceOffsetOrigin LastMatchedSourceOffsetOrigin { get; internal set; }
|
||||
|
||||
/// <summary>
|
||||
/// The offset the calibrator MEASURED for the source file, which is not necessarily the
|
||||
/// one applied.
|
||||
/// <para>
|
||||
/// Since the 2026-08-20 revert the measurement is observational only: it is recorded so the
|
||||
/// field tells us what an era-aware calibrator would have to work with, without acting on
|
||||
/// it. Reported separately from <see cref="LastMatchedSourceOffsetMinutes"/> precisely so
|
||||
/// the two can never be confused — that event said "calibrated" while carrying a wrong
|
||||
/// value, and an honest record has to distinguish measured from applied.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public int? LastMatchedMeasuredWriterOffsetMinutes { get; internal set; }
|
||||
|
||||
// Callbacks to EnrollmentTracker
|
||||
public Action<string> OnEspPhaseChanged { get; set; }
|
||||
public Action<string> OnImeAgentVersion { get; set; }
|
||||
|
||||
+50
-1
@@ -65,6 +65,42 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
state.LastReadTime = DateTime.UtcNow;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Records that the file was looked at in a poll pass — whether or not it had new data.
|
||||
/// Creates the entry on first sight (position 0), so a file first seen EMPTY counts as
|
||||
/// observed and its first content is provably fresh.
|
||||
/// <para>
|
||||
/// This timestamp is the freshness reference for per-line offset anchoring: bytes found
|
||||
/// in the NEXT pass were written after this instant, so
|
||||
/// <c>now - LastCheckedUtc</c> bounds the age of every line in that pass's chunk.
|
||||
/// The caller supplies the clock (the tracker's <c>UtcNowProvider</c>) so replay/test
|
||||
/// clocks stay consistent with the freshness comparison.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public void MarkChecked(string filePath, DateTime nowUtc)
|
||||
{
|
||||
FilePositionState state;
|
||||
if (!_positions.TryGetValue(filePath, out state))
|
||||
{
|
||||
state = new FilePositionState();
|
||||
_positions[filePath] = state;
|
||||
}
|
||||
|
||||
state.LastCheckedUtc = nowUtc;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// When the file was last looked at, or <see cref="DateTime.MinValue"/> when it never
|
||||
/// was in THIS process — including entries restored from persisted state, whose
|
||||
/// bookmark survives an agent restart but whose freshness deliberately does not
|
||||
/// (the restart gap can hold arbitrarily old backlog).
|
||||
/// </summary>
|
||||
public DateTime GetLastCheckedUtc(string filePath)
|
||||
{
|
||||
FilePositionState state;
|
||||
return _positions.TryGetValue(filePath, out state) ? state.LastCheckedUtc : DateTime.MinValue;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Gets the stored position for a file, or 0 if not tracked.
|
||||
/// Does not perform rollover detection.
|
||||
@@ -89,6 +125,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// <summary>
|
||||
/// Restores a previously persisted position for a file.
|
||||
/// Used on agent restart to continue reading from the last known position.
|
||||
/// <para>
|
||||
/// <see cref="FilePositionState.LastCheckedUtc"/> is deliberately NOT restored: the
|
||||
/// bookmark survives the restart, the freshness guarantee does not — the first pass
|
||||
/// after a restart reads the whole downtime backlog and must never anchor per-line
|
||||
/// offsets on it.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public void RestorePosition(string filePath, long position, long lastKnownSize)
|
||||
{
|
||||
@@ -96,7 +138,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
Position = position,
|
||||
LastKnownSize = lastKnownSize,
|
||||
LastReadTime = DateTime.UtcNow
|
||||
LastReadTime = DateTime.UtcNow,
|
||||
LastCheckedUtc = DateTime.MinValue
|
||||
};
|
||||
}
|
||||
}
|
||||
@@ -106,5 +149,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
public long Position { get; set; }
|
||||
public long LastKnownSize { get; set; }
|
||||
public DateTime LastReadTime { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// When this file was last looked at by a poll pass IN THIS PROCESS. In-memory only —
|
||||
/// never persisted, so a restart resets it (see <see cref="LogFilePositionTracker.RestorePosition"/>).
|
||||
/// </summary>
|
||||
public DateTime LastCheckedUtc { get; set; }
|
||||
}
|
||||
}
|
||||
|
||||
@@ -407,6 +407,13 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
var offsetMinutes = _tracker.LastMatchedSourceOffsetMinutes;
|
||||
if (offsetMinutes.HasValue)
|
||||
data["sourceOffsetMinutes"] = offsetMinutes.Value.ToString(culture);
|
||||
|
||||
// Observational only — what the calibrator measured, which since the 2026-08-20
|
||||
// revert is deliberately NOT what was applied. Kept separate so the two can never
|
||||
// be read as the same thing.
|
||||
var measured = _tracker.LastMatchedMeasuredWriterOffsetMinutes;
|
||||
if (measured.HasValue)
|
||||
data["measuredWriterOffsetMinutes"] = measured.Value.ToString(culture);
|
||||
}
|
||||
|
||||
if (!derivedFromClock) return;
|
||||
@@ -420,9 +427,14 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
switch (origin)
|
||||
{
|
||||
case CmTraceOffsetOrigin.Bias: return "bias";
|
||||
// Per-FILE offset application, retired by the 2026-08-20 revert (04b1a7c6).
|
||||
// Kept so stored 2.0.1410 events remain interpretable; no current path emits it.
|
||||
case CmTraceOffsetOrigin.Calibrated: return "calibrated";
|
||||
// The writer's offset was never measured, so this process's own zone was assumed —
|
||||
// correct only if the writer happens to share it.
|
||||
// The line anchored itself: read provably fresh, its own distance to the agent
|
||||
// clock (grid-rounded) was applied as the writer's offset. Era-safe per line.
|
||||
case CmTraceOffsetOrigin.LineAnchored: return "line-anchored";
|
||||
// The line was not provably fresh (backlog, restart catch-up, replay), so this
|
||||
// process's own zone was assumed — correct only if the writer happens to share it.
|
||||
default: return "reader-zone-fallback";
|
||||
}
|
||||
}
|
||||
|
||||
+6
@@ -119,6 +119,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Transport.Telemetry
|
||||
AddSecurityHeaders(request);
|
||||
request.Headers.Add("X-Correlation-ID", correlationId);
|
||||
|
||||
// P14: device-clock send time, one value per request. Lets the backend separate
|
||||
// spool delay (SentAt − OccurredUtc, both device frame) from device-vs-server
|
||||
// clock offset (ReceivedAt − SentAt) — indistinguishable without this header.
|
||||
// Stamped per attempt on purpose: a retry after backoff is a NEW send moment.
|
||||
request.Headers.Add("X-Send-Time-Utc", DateTime.UtcNow.ToString("O"));
|
||||
|
||||
HttpResponseMessage response;
|
||||
try
|
||||
{
|
||||
|
||||
@@ -0,0 +1,152 @@
|
||||
using AutopilotMonitor.Functions.Services;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
|
||||
namespace AutopilotMonitor.Functions.Tests;
|
||||
|
||||
/// <summary>
|
||||
/// Pins the CMTrace time-skew regression tripwire (CmTraceSkewTripwire.Evaluate): fires only
|
||||
/// when the IME-vs-other median delta divergence sits on the 15-minute offset grid (residual
|
||||
/// < 2 min) AND both sides have enough samples over enough distinct upload batches. The
|
||||
/// tripwire's goal state is to never fire, so the must-stay-silent directions are the primary
|
||||
/// cases: off-grid replays, sub-grid divergence, thin samples, batch-composition artifacts,
|
||||
/// and common-mode spool latency must all pass without a hit.
|
||||
/// </summary>
|
||||
public class CmTraceSkewTripwireTests
|
||||
{
|
||||
/// <summary>Scan with the given per-side medians, comfortably above all sample/batch minimums.</summary>
|
||||
private static SessionSkewScan MakeScan(
|
||||
double imeDeltaMinutes, double otherDeltaMinutes,
|
||||
int imeSamples = 30, int otherSamples = 30,
|
||||
int imeBatches = 5, int otherBatches = 5)
|
||||
{
|
||||
var scan = new SessionSkewScan
|
||||
{
|
||||
ImeDistinctBatchCount = imeBatches,
|
||||
OtherDistinctBatchCount = otherBatches,
|
||||
};
|
||||
for (int i = 0; i < imeSamples; i++)
|
||||
scan.ImeDeltaMinutes.Add(imeDeltaMinutes);
|
||||
for (int i = 0; i < otherSamples; i++)
|
||||
scan.OtherDeltaMinutes.Add(otherDeltaMinutes);
|
||||
return scan;
|
||||
}
|
||||
|
||||
// ── Must fire ──────────────────────────────────────────────────────────
|
||||
|
||||
[Fact]
|
||||
public void Fires_OnLargeNegativeGridDivergence()
|
||||
{
|
||||
// −540 min = the field-measured E.-Australia-style skew (−9 h), exactly 36 grid steps.
|
||||
// Both sides share 1.2 min upload latency — it cancels in the difference.
|
||||
var result = CmTraceSkewTripwire.Evaluate(MakeScan(imeDeltaMinutes: -538.8, otherDeltaMinutes: 1.2));
|
||||
|
||||
Assert.NotNull(result);
|
||||
Assert.Equal(-36, result!.GridSteps);
|
||||
Assert.Equal(-540.0, result.DiffMinutes, 3);
|
||||
Assert.True(result.ResidualMinutes < CmTraceSkewTripwire.ResidualToleranceMinutes);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Fires_OnSingleGridStepWithBoundaryResidual()
|
||||
{
|
||||
// +15 min divergence with residual 1.9 — just inside the 2-min tolerance.
|
||||
var result = CmTraceSkewTripwire.Evaluate(MakeScan(imeDeltaMinutes: 16.9, otherDeltaMinutes: 0.0));
|
||||
|
||||
Assert.NotNull(result);
|
||||
Assert.Equal(1, result!.GridSteps);
|
||||
Assert.Equal(1.9, result.ResidualMinutes, 3);
|
||||
}
|
||||
|
||||
// ── Must stay silent ───────────────────────────────────────────────────
|
||||
|
||||
[Fact]
|
||||
public void Silent_WhenResidualOffGrid()
|
||||
{
|
||||
// 17.5 min divergence: nearest grid step is 15, residual 2.5 ≥ tolerance — the replay
|
||||
// signature (old log lines re-read late land anywhere, not on the zone grid).
|
||||
Assert.Null(CmTraceSkewTripwire.Evaluate(MakeScan(imeDeltaMinutes: 17.5, otherDeltaMinutes: 0.0)));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Silent_WhenDivergenceBelowOneGridStep()
|
||||
{
|
||||
// 9 min rounds to 1 step but with residual 6 — and 7 min rounds to 0 steps. Both silent.
|
||||
Assert.Null(CmTraceSkewTripwire.Evaluate(MakeScan(imeDeltaMinutes: 9.0, otherDeltaMinutes: 0.0)));
|
||||
Assert.Null(CmTraceSkewTripwire.Evaluate(MakeScan(imeDeltaMinutes: 7.0, otherDeltaMinutes: 0.0)));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Silent_WhenImeSampleCountBelowMinimum()
|
||||
{
|
||||
var scan = MakeScan(imeDeltaMinutes: -540.0, otherDeltaMinutes: 0.0,
|
||||
imeSamples: CmTraceSkewTripwire.MinSamplesPerSide - 1);
|
||||
Assert.Null(CmTraceSkewTripwire.Evaluate(scan));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Silent_WhenDistinctBatchesBelowMinimum()
|
||||
{
|
||||
// A perfect grid divergence backed by only 2 upload batches on one side is a
|
||||
// batch-composition artifact (ReceivedAt is stamped per batch, not per event).
|
||||
var scan = MakeScan(imeDeltaMinutes: -540.0, otherDeltaMinutes: 0.0,
|
||||
otherBatches: CmTraceSkewTripwire.MinDistinctBatchesPerSide - 1);
|
||||
Assert.Null(CmTraceSkewTripwire.Evaluate(scan));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Silent_OnCommonModeSpoolLatency()
|
||||
{
|
||||
// Offline spool: BOTH sides uploaded 45 min late. The difference of medians is ~0 —
|
||||
// shared latency must cancel, never read as skew.
|
||||
Assert.Null(CmTraceSkewTripwire.Evaluate(MakeScan(imeDeltaMinutes: 45.3, otherDeltaMinutes: 45.1)));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Silent_OnNullOrEmptyScan()
|
||||
{
|
||||
Assert.Null(CmTraceSkewTripwire.Evaluate(null));
|
||||
Assert.Null(CmTraceSkewTripwire.Evaluate(new SessionSkewScan()));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void MedianIsRobustAgainstMinorityOutliers()
|
||||
{
|
||||
// A handful of replayed old lines (huge off-grid deltas) inside an otherwise healthy
|
||||
// IME stream must not drag the median onto the grid.
|
||||
var scan = MakeScan(imeDeltaMinutes: 0.5, otherDeltaMinutes: 0.4);
|
||||
scan.ImeDeltaMinutes.Add(-1327.0);
|
||||
scan.ImeDeltaMinutes.Add(-738.0);
|
||||
Assert.Null(CmTraceSkewTripwire.Evaluate(scan));
|
||||
}
|
||||
|
||||
// ── Bias suppression predicate ─────────────────────────────────────────
|
||||
|
||||
[Fact]
|
||||
public void BiasDominated_WhenBiasIsHalfOrMore()
|
||||
{
|
||||
Assert.True(CmTraceSkewTripwire.IsBiasDominated(new Dictionary<string, int>
|
||||
{
|
||||
["bias"] = 50,
|
||||
["line-anchored"] = 50,
|
||||
}));
|
||||
Assert.True(CmTraceSkewTripwire.IsBiasDominated(new Dictionary<string, int>
|
||||
{
|
||||
["Bias"] = 3, // case-insensitive
|
||||
}));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void NotBiasDominated_WhenAnchoredMajorityOrNoData()
|
||||
{
|
||||
Assert.False(CmTraceSkewTripwire.IsBiasDominated(new Dictionary<string, int>
|
||||
{
|
||||
["bias"] = 10,
|
||||
["line-anchored"] = 80,
|
||||
["reader-zone-fallback"] = 11,
|
||||
}));
|
||||
// Empty/missing histogram fails open toward reporting — a storage error must not
|
||||
// silently swallow a genuine regression hit.
|
||||
Assert.False(CmTraceSkewTripwire.IsBiasDominated(new Dictionary<string, int>()));
|
||||
Assert.False(CmTraceSkewTripwire.IsBiasDominated(null));
|
||||
}
|
||||
}
|
||||
@@ -33,6 +33,31 @@ public class IngestCriticalPathTests
|
||||
Assert.All(events, evt => Assert.Equal(receivedAt, evt.ReceivedAt));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void StampServerFields_SetsSentAtOnAllEvents_AndOverridesAgentValues()
|
||||
{
|
||||
// P14: SentAt is request-level and server-stamped — a per-event value coming off the
|
||||
// wire (agent bug, forged payload) must never survive.
|
||||
var sentAt = DateTime.UtcNow.AddSeconds(-4);
|
||||
var events = MakeEvents(3);
|
||||
events[1].SentAt = DateTime.UtcNow.AddYears(1);
|
||||
|
||||
EventIngestProcessor.StampServerFields(events, ValidTenantId, ValidSessionId, DateTime.UtcNow, sentAt);
|
||||
|
||||
Assert.All(events, evt => Assert.Equal(sentAt, evt.SentAt));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void StampServerFields_WithoutSendTimeHeader_LeavesSentAtNull()
|
||||
{
|
||||
var events = MakeEvents(2);
|
||||
events[0].SentAt = DateTime.UtcNow; // forged per-event value must be cleared, not kept
|
||||
|
||||
EventIngestProcessor.StampServerFields(events, ValidTenantId, ValidSessionId, DateTime.UtcNow);
|
||||
|
||||
Assert.All(events, evt => Assert.Null(evt.SentAt));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void StampServerFields_SetsTenantIdOnAllEvents()
|
||||
{
|
||||
|
||||
@@ -43,6 +43,45 @@ public class IngestTelemetryFunctionTests
|
||||
Assert.Equal(string.Empty, session);
|
||||
}
|
||||
|
||||
// ============================================================ X-Send-Time-Utc parsing (P14)
|
||||
|
||||
[Fact]
|
||||
public void ParseSendTimeHeader_RoundTripUtc_ParsesToUtc()
|
||||
{
|
||||
var parsed = IngestTelemetryFunction.ParseSendTimeHeader("2026-08-21T10:15:30.1234567Z");
|
||||
|
||||
Assert.Equal(new DateTime(2026, 8, 21, 10, 15, 30, DateTimeKind.Utc).AddTicks(1234567), parsed);
|
||||
Assert.Equal(DateTimeKind.Utc, parsed!.Value.Kind);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void ParseSendTimeHeader_OffsetValue_NormalizedToUtc()
|
||||
{
|
||||
var parsed = IngestTelemetryFunction.ParseSendTimeHeader("2026-08-21T12:15:30+02:00");
|
||||
|
||||
Assert.Equal(new DateTime(2026, 8, 21, 10, 15, 30, DateTimeKind.Utc), parsed);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void ParseSendTimeHeader_FutureDatedValue_KeptVerbatim()
|
||||
{
|
||||
// A future send time IS the device-clock-error measurement — no upper clamp.
|
||||
var parsed = IngestTelemetryFunction.ParseSendTimeHeader("2027-01-01T00:00:00Z");
|
||||
|
||||
Assert.Equal(new DateTime(2027, 1, 1, 0, 0, 0, DateTimeKind.Utc), parsed);
|
||||
}
|
||||
|
||||
[Theory]
|
||||
[InlineData(null)]
|
||||
[InlineData("")]
|
||||
[InlineData(" ")]
|
||||
[InlineData("not-a-date")]
|
||||
[InlineData("1999-12-31T23:59:59Z")] // pre-2000 can only be garbage (Table Storage floor guard)
|
||||
public void ParseSendTimeHeader_AbsentOrGarbage_ReturnsNull(string? headerValue)
|
||||
{
|
||||
Assert.Null(IngestTelemetryFunction.ParseSendTimeHeader(headerValue));
|
||||
}
|
||||
|
||||
// ============================================================ Payload size-cap guard
|
||||
|
||||
[Fact]
|
||||
|
||||
@@ -200,4 +200,120 @@ public class ReportAgentErrorFunctionTests
|
||||
|
||||
Assert.Empty(h.OpsEvents);
|
||||
}
|
||||
|
||||
// =========================================================================
|
||||
// MaterializeIntegrityMismatchAsync — an IntegrityCheckFailed report becomes an
|
||||
// AgentBinaryIntegrityMismatch ops event, UNLESS it is the known release race
|
||||
// (agents comparing against hash snapshots that don't belong to their own binary;
|
||||
// AdminConfig cache TTL 5 min). e9753578 proved the race: a genuine 1410 exe was
|
||||
// compared against the cached 1409 hash and reported a "mismatch" that cost a day
|
||||
// of mis-attributed root-causing while sitting invisible in App Insights.
|
||||
// =========================================================================
|
||||
|
||||
private const string RunningExeSha = "5fca975e43fa5fca975e43fa5fca975e43fa5fca975e43fa5fca975e43fa0000";
|
||||
private const string PublishedExeSha = "8ebaa060ad348ebaa060ad348ebaa060ad348ebaa060ad348ebaa060ad340000";
|
||||
|
||||
private static AgentErrorReport IntegrityReport(
|
||||
string? sessionId = SessionId, string agentVersion = "2.0.1410", string? actualSha = null) => new()
|
||||
{
|
||||
SessionId = sessionId!,
|
||||
TenantId = TenantId,
|
||||
ErrorType = AgentErrorType.IntegrityCheckFailed,
|
||||
Message = $"Running exe SHA-256 differs from backend-advertised hash. actual={actualSha ?? RunningExeSha}, expected={PublishedExeSha}",
|
||||
AgentVersion = agentVersion,
|
||||
Timestamp = Now,
|
||||
};
|
||||
|
||||
private static Task RunIntegrityAsync(
|
||||
Harness h, AgentErrorReport report,
|
||||
string? latestVersion = "2.0.1410", string? latestExeSha = PublishedExeSha)
|
||||
=> ReportAgentErrorFunction.MaterializeIntegrityMismatchAsync(
|
||||
report, TenantId, h.OpsService, latestVersion, latestExeSha,
|
||||
NullLogger<ReportAgentErrorFunction>.Instance);
|
||||
|
||||
[Fact]
|
||||
public async Task SameVersion_with_unknown_binary_records_ops_event()
|
||||
{
|
||||
// The real signal: an agent claiming the LATEST version whose running exe is NOT
|
||||
// the published one — tamper, stale blob, or a build outside the release pipeline.
|
||||
var h = new Harness();
|
||||
|
||||
await RunIntegrityAsync(h, IntegrityReport());
|
||||
|
||||
var ops = Assert.Single(h.OpsEvents);
|
||||
Assert.Equal("AgentBinaryIntegrityMismatch", ops.EventType);
|
||||
Assert.Equal(TenantId, ops.TenantId);
|
||||
Assert.Contains("actual=5fca", ops.Message);
|
||||
Assert.Contains("2.0.1410", ops.Message);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task RunningHash_equal_to_published_exe_is_suppressed_as_stale_expectation()
|
||||
{
|
||||
// e9753578's exact shape: the device RUNS the published binary; only its cached
|
||||
// expectation was the previous release's hash. Self-heals — must not alert.
|
||||
var h = new Harness();
|
||||
|
||||
await RunIntegrityAsync(h, IntegrityReport(actualSha: PublishedExeSha));
|
||||
|
||||
Assert.Empty(h.OpsEvents);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Older_agent_version_than_latest_is_suppressed_as_update_race()
|
||||
{
|
||||
// The long-known direction: version N agent sees version N+1's hash right after a
|
||||
// release; the forced self-update heals it.
|
||||
var h = new Harness();
|
||||
|
||||
await RunIntegrityAsync(h, IntegrityReport(agentVersion: "2.0.1409+d43cfe2b"), latestVersion: "2.0.1410");
|
||||
|
||||
Assert.Empty(h.OpsEvents);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Version_with_commit_suffix_matches_latest_without_suffix()
|
||||
{
|
||||
// Agent versions carry "+<commit>", AdminConfiguration does not — the comparison
|
||||
// must normalize, otherwise every genuine mismatch would look like a version race.
|
||||
var h = new Harness();
|
||||
|
||||
await RunIntegrityAsync(h, IntegrityReport(agentVersion: "2.0.1410+3b59dab2df6c"));
|
||||
|
||||
Assert.Single(h.OpsEvents);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Missing_latest_config_fails_open_to_recording()
|
||||
{
|
||||
// No published-version info available → visibility wins over suppression.
|
||||
var h = new Harness();
|
||||
|
||||
await RunIntegrityAsync(h, IntegrityReport(), latestVersion: null, latestExeSha: null);
|
||||
|
||||
Assert.Single(h.OpsEvents);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Integrity_mismatch_without_session_id_still_records_ops_event()
|
||||
{
|
||||
// The report can arrive before session registration — the binary evidence must
|
||||
// never be dropped for lack of a session.
|
||||
var h = new Harness();
|
||||
|
||||
await RunIntegrityAsync(h, IntegrityReport(sessionId: null));
|
||||
|
||||
var ops = Assert.Single(h.OpsEvents);
|
||||
Assert.Equal("AgentBinaryIntegrityMismatch", ops.EventType);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Other_error_types_do_not_record_integrity_ops_event()
|
||||
{
|
||||
var h = new Harness();
|
||||
|
||||
await RunIntegrityAsync(h, Report(Now));
|
||||
|
||||
Assert.Empty(h.OpsEvents);
|
||||
}
|
||||
}
|
||||
|
||||
@@ -0,0 +1,450 @@
|
||||
using AutopilotMonitor.Functions.Services;
|
||||
using AutopilotMonitor.Shared.DataAccess;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
using Microsoft.Extensions.Logging.Abstractions;
|
||||
using Moq;
|
||||
|
||||
namespace AutopilotMonitor.Functions.Tests;
|
||||
|
||||
/// <summary>
|
||||
/// Pins the clock_skew condition source (EvaluateClockSkewCondition) behind ANALYZE-DEV-008.
|
||||
/// The evaluator measures d = Timestamp − ReceivedAt per event, reduces to per-upload-batch
|
||||
/// medians (wide-spread batches = spool backlogs are dropped), then detects either a persistent
|
||||
/// mid-session step between two flat plateaus (clock_jump) or a stable whole-session offset
|
||||
/// (sustained_offset). IME-log-derived events are excluded so a CMTrace anchoring regression
|
||||
/// (the e9753578 field incident) can never fire this customer-facing rule — that failure mode
|
||||
/// belongs to the operator-side CmTraceSkewTripwire.
|
||||
/// </summary>
|
||||
public class RuleEngineClockSkewTests
|
||||
{
|
||||
private const string TenantId = "a1b2c3d4-e5f6-7890-abcd-ef1234567890";
|
||||
private const string SessionId = "b2c3d4e5-f6a7-8901-bcde-f12345678901";
|
||||
|
||||
private static readonly DateTime T0 = new(2026, 8, 20, 10, 0, 0, DateTimeKind.Utc);
|
||||
|
||||
// ── clock_jump: must fire ──────────────────────────────────────────────
|
||||
|
||||
[Fact]
|
||||
public async Task ClockJump_ForwardStepBetweenStableFrames_Fires()
|
||||
{
|
||||
// 4 batches on frame 0, then 4 batches on frame +1800 s (+30 min) that hold to
|
||||
// session end — the canonical "clock corrected forward mid-session".
|
||||
var events = Batches(offsetsSeconds: new double[] { 0, 0, 0, 0, 1800, 1800, 1800, 1800 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
var result = Assert.Single(outcome.Results);
|
||||
var evidence = Assert.IsAssignableFrom<IDictionary<string, object>>(result.MatchedConditions["clock_jump"]);
|
||||
Assert.Equal("forward", evidence["direction"]);
|
||||
Assert.Equal(1800, Convert.ToDouble(evidence["jumpSeconds"]), 0);
|
||||
Assert.Equal("skewSummary", evidence["field"]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task ClockJump_BackwardStep_Fires()
|
||||
{
|
||||
var events = Batches(new double[] { 0, 0, 0, -1200, -1200, -1200 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
var result = Assert.Single(outcome.Results);
|
||||
var evidence = Assert.IsAssignableFrom<IDictionary<string, object>>(result.MatchedConditions["clock_jump"]);
|
||||
Assert.Equal("backward", evidence["direction"]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task ClockJump_WrongClockCorrectedMidSession_Fires()
|
||||
{
|
||||
// Device started 30 min behind, time sync fixed it: the CORRECTED frame is the
|
||||
// persistent change, so this must fire (direction forward).
|
||||
var events = Batches(new double[] { -1800, -1800, -1800, 0, 0, 0 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
var result = Assert.Single(outcome.Results);
|
||||
var evidence = Assert.IsAssignableFrom<IDictionary<string, object>>(result.MatchedConditions["clock_jump"]);
|
||||
Assert.Equal("forward", evidence["direction"]);
|
||||
}
|
||||
|
||||
// ── clock_jump: must stay silent ───────────────────────────────────────
|
||||
|
||||
[Fact]
|
||||
public async Task ClockJump_ImeDerivedSkew_ExcludedFromMeasurement_Silent()
|
||||
{
|
||||
// e9753578 replica: IME-derived events carry grid-multiple wrong timestamps (−7 h /
|
||||
// +2 h writer eras) while the agent's own events are healthy. The IME events must be
|
||||
// excluded up front — a CMTrace anchoring regression may NEVER fire the customer rule.
|
||||
var events = Batches(new double[] { 0, 0, 0, 0, 0, 0 });
|
||||
var seq = 1000;
|
||||
foreach (var imeOffset in new double[] { -25200, -25200, 7200, 7200, -25200, 7200 })
|
||||
events.Add(MakeEvent(seq++, T0.AddMinutes(seq % 7), imeOffset, source: "ImeLogTracker"));
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task ClockJump_WideSpreadSpoolBatch_DroppedAndSilent()
|
||||
{
|
||||
// One upload batch whose events span 30 min of emission time (offline spool flushed
|
||||
// in a single request) — the internal spread disqualifies the batch entirely.
|
||||
var events = Batches(new double[] { 0, 0, 0, 0, 0, 0 });
|
||||
var flushReceivedAt = T0.AddMinutes(90);
|
||||
for (int i = 0; i < 20; i++)
|
||||
events.Add(MakeEvent(2000 + i, flushReceivedAt, offsetSeconds: -1800 + i * 90));
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task ClockJump_GradualBacklogDrainRamp_Silent()
|
||||
{
|
||||
// A chunked spool drain produces a RAMP of batch medians walking back to the live
|
||||
// frame. No flat pre/post plateau pair exists, so the step detector must reject every
|
||||
// candidate — this is a delivery artifact, not a clock change.
|
||||
var events = Batches(new double[] { -1800, -1500, -1200, -900, -600, -300, 0, 0 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task ClockJump_TransientExcursionReturnsToFrame_Silent()
|
||||
{
|
||||
// Frame dips for two batches and returns — whatever it was, it is not a SUSTAINED
|
||||
// clock change (end-state persistence fails).
|
||||
var events = Batches(new double[] { 0, 0, 0, -1800, -1800, 0, 0, 0 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task ClockJump_BelowThreshold_Silent()
|
||||
{
|
||||
var events = Batches(new double[] { 0, 0, 0, 240, 240, 240 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task ClockJump_TooFewBatches_Silent()
|
||||
{
|
||||
// 5 batches < 2×ConfirmBatches — not enough for two comparison windows.
|
||||
var events = Batches(new double[] { 0, 0, 1800, 1800, 1800 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task ClockJump_LegacyEventsWithoutReceivedAt_Silent()
|
||||
{
|
||||
var events = Batches(new double[] { 0, 0, 0, 1800, 1800, 1800 });
|
||||
foreach (var e in events)
|
||||
e.ReceivedAt = null;
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task ClockJump_ClampedEventsExcluded_Silent()
|
||||
{
|
||||
// The jumped frame exists only on clamped events (their OccurredUtc is already
|
||||
// server-substituted in production) — excluding them leaves a single stable frame.
|
||||
var events = Batches(new double[] { 0, 0, 0, 0, 0, 0 });
|
||||
var seq = 3000;
|
||||
foreach (var offset in new double[] { 1800, 1800, 1800 })
|
||||
{
|
||||
var evt = MakeEvent(seq, T0.AddMinutes(120 + seq % 5), offset);
|
||||
evt.TimestampClamped = true;
|
||||
events.Add(evt);
|
||||
seq++;
|
||||
}
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
// ── sustained_offset ───────────────────────────────────────────────────
|
||||
|
||||
[Fact]
|
||||
public async Task SustainedOffset_ClockBehindWholeSession_Fires()
|
||||
{
|
||||
var events = Batches(new double[] { -1800, -1795, -1805, -1800, -1798 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("sustained_offset", "300"), events);
|
||||
|
||||
var result = Assert.Single(outcome.Results);
|
||||
var evidence = Assert.IsAssignableFrom<IDictionary<string, object>>(result.MatchedConditions["sustained_offset"]);
|
||||
Assert.Equal("behind", evidence["direction"]);
|
||||
Assert.Equal(-30.0, Convert.ToDouble(evidence["offsetMinutes"]), 1);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task SustainedOffset_HealthyUploadLatencyBaseline_Silent()
|
||||
{
|
||||
// Healthy devices sit a few seconds NEGATIVE (upload latency) — far below threshold.
|
||||
var events = Batches(new double[] { -3, -5, -2, -4, -6 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("sustained_offset", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task SustainedOffset_UnstableBatchOffsets_Silent()
|
||||
{
|
||||
// Medians all over the place: no honest single-offset statement exists, even though
|
||||
// the overall median magnitude clears the threshold.
|
||||
var events = Batches(new double[] { -2400, 900, -1800, 300, -3600, -600 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("sustained_offset", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
// ── P14: SentAt direct measurement (X-Send-Time-Utc batches) ───────────
|
||||
|
||||
[Fact]
|
||||
public async Task SentAt_SpoolFlushWithWideEventSpread_JumpStillMeasured_Fires()
|
||||
{
|
||||
// Every batch is a spool flush spanning 30 min of emission time — the legacy path
|
||||
// drops ALL of them via the spread cap and stays blind. SentAt measures the frame
|
||||
// crossing directly, so the +30 min step must fire regardless of event-timestamp
|
||||
// spread, and every batch counts as a SentAt batch.
|
||||
static double[] Wide(int _) => new double[] { -1800, -1350, -900, -450, 0 };
|
||||
var events = SentAtBatches(new double[] { 0, 0, 0, 0, 1800, 1800, 1800, 1800 }, Wide);
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
var result = Assert.Single(outcome.Results);
|
||||
var evidence = Assert.IsAssignableFrom<IDictionary<string, object>>(result.MatchedConditions["clock_jump"]);
|
||||
Assert.Equal("forward", evidence["direction"]);
|
||||
Assert.Equal(8, Convert.ToInt32(evidence["sentAtBatchCount"]));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task SentAt_UniformBacklogBatches_ReadAsHealthy_Silent()
|
||||
{
|
||||
// EXACTLY the event shape of SustainedOffset_ClockBehindWholeSession_Fires (tight
|
||||
// −30 min Timestamp−ReceivedAt deltas), but the batches carry SentAt ≈ ReceivedAt:
|
||||
// the device clock is fine, the events are merely OLD (uniform spool backlog).
|
||||
// The legacy median cannot tell those apart — SentAt can, and must stay silent.
|
||||
static double[] Backlog(int b) => new double[] { -1800, -1795, -1805, -1800, -1798 };
|
||||
var events = SentAtBatches(new double[] { -3, -5, -2, -4, -6 }, Backlog);
|
||||
|
||||
var outcome = await RunAsync(MakeRule("sustained_offset", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task SentAt_SustainedOffset_MeasuredFromSendTime_Fires()
|
||||
{
|
||||
var events = SentAtBatches(new double[] { -1800, -1795, -1805, -1800, -1798 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("sustained_offset", "300"), events);
|
||||
|
||||
var result = Assert.Single(outcome.Results);
|
||||
var evidence = Assert.IsAssignableFrom<IDictionary<string, object>>(result.MatchedConditions["sustained_offset"]);
|
||||
Assert.Equal("behind", evidence["direction"]);
|
||||
Assert.Equal(-30.0, Convert.ToDouble(evidence["offsetMinutes"]), 1);
|
||||
Assert.Equal(5, Convert.ToInt32(evidence["sentAtBatchCount"]));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task SentAt_ImeOnlyBatches_MeasurableViaSendTime_Fires()
|
||||
{
|
||||
// IME-source events are excluded from the LEGACY measurement (writer timezone
|
||||
// belief), but a SentAt batch never reads event timestamps — the device clock is
|
||||
// measured from the send moment, so IME-only sessions become measurable.
|
||||
var events = SentAtBatches(
|
||||
new double[] { -1800, -1800, -1800, -1800, -1800 }, source: "ImeLogTracker");
|
||||
|
||||
var outcome = await RunAsync(MakeRule("sustained_offset", "300"), events);
|
||||
|
||||
var result = Assert.Single(outcome.Results);
|
||||
var evidence = Assert.IsAssignableFrom<IDictionary<string, object>>(result.MatchedConditions["sustained_offset"]);
|
||||
Assert.Equal("behind", evidence["direction"]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task SentAt_HealthyUploadLatencyBaseline_Silent()
|
||||
{
|
||||
var events = SentAtBatches(new double[] { -3, -5, -2, -4, -6 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("sustained_offset", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task SentAt_MixedWithLegacyBatches_ConsistentFrame_Fires()
|
||||
{
|
||||
// Mid-session agent update: first half legacy (event-median), second half SentAt.
|
||||
// Both measure the same physical quantity, so a consistent −30 min frame across the
|
||||
// mix must still produce a sustained-offset verdict.
|
||||
var events = Batches(new double[] { -1800, -1795, -1805 });
|
||||
long seq = 1000;
|
||||
for (int b = 0; b < 3; b++)
|
||||
{
|
||||
var receivedAt = T0.AddMinutes(60 + b * 5);
|
||||
var sentAt = receivedAt.AddSeconds(-1800);
|
||||
for (int i = 0; i < 5; i++)
|
||||
{
|
||||
var evt = MakeEvent(seq++, receivedAt, -1800 + (i - 2));
|
||||
evt.SentAt = sentAt;
|
||||
events.Add(evt);
|
||||
}
|
||||
}
|
||||
|
||||
var outcome = await RunAsync(MakeRule("sustained_offset", "300"), events);
|
||||
|
||||
var result = Assert.Single(outcome.Results);
|
||||
var evidence = Assert.IsAssignableFrom<IDictionary<string, object>>(result.MatchedConditions["sustained_offset"]);
|
||||
Assert.Equal(-30.0, Convert.ToDouble(evidence["offsetMinutes"]), 1);
|
||||
Assert.Equal(3, Convert.ToInt32(evidence["sentAtBatchCount"]));
|
||||
Assert.Equal(6, Convert.ToInt32(evidence["batchCount"]));
|
||||
}
|
||||
|
||||
// ── ANALYZE-DEV-008 shape: two optional conditions ─────────────────────
|
||||
|
||||
[Fact]
|
||||
public async Task Dev008Shape_JumpOnlySession_FiresWithSingleMatchedCondition()
|
||||
{
|
||||
// Mirrors the shipped rule: both conditions required:false, baseConfidence 60,
|
||||
// threshold 50 — one matching metric must be enough to fire.
|
||||
var rule = MakeRule("clock_jump", "300");
|
||||
rule.Conditions[0].Required = false;
|
||||
rule.Conditions.Add(new RuleCondition
|
||||
{
|
||||
Signal = "sustained_offset",
|
||||
Source = "clock_skew",
|
||||
SkewMetric = "sustained_offset",
|
||||
Operator = "gte",
|
||||
Value = "300",
|
||||
Required = false,
|
||||
});
|
||||
|
||||
var events = Batches(new double[] { 0, 0, 0, 0, 1800, 1800, 1800, 1800 });
|
||||
|
||||
var outcome = await RunAsync(rule, events);
|
||||
|
||||
var result = Assert.Single(outcome.Results);
|
||||
Assert.True(result.MatchedConditions.ContainsKey("clock_jump"));
|
||||
}
|
||||
|
||||
// ===== Helpers =====
|
||||
|
||||
private static AnalyzeRule MakeRule(string skewMetric, string thresholdSeconds) => new()
|
||||
{
|
||||
RuleId = "ANALYZE-TST-CLK",
|
||||
Title = "clock_skew test rule",
|
||||
Severity = "warning",
|
||||
Category = "device",
|
||||
Enabled = true,
|
||||
IsBuiltIn = false,
|
||||
BaseConfidence = 60,
|
||||
ConfidenceThreshold = 50,
|
||||
Conditions = new List<RuleCondition>
|
||||
{
|
||||
new()
|
||||
{
|
||||
Signal = skewMetric,
|
||||
Source = "clock_skew",
|
||||
SkewMetric = skewMetric,
|
||||
Operator = "gte",
|
||||
Value = thresholdSeconds,
|
||||
Required = true,
|
||||
}
|
||||
},
|
||||
Explanation = "test {{skewSummary}}",
|
||||
};
|
||||
|
||||
/// <summary>
|
||||
/// One upload batch per entry: 5 events sharing the batch's ReceivedAt, each with
|
||||
/// Timestamp = ReceivedAt + offsetSeconds (±2 s in-batch jitter, well under the spread cap).
|
||||
/// </summary>
|
||||
private static List<EnrollmentEvent> Batches(double[] offsetsSeconds)
|
||||
{
|
||||
var events = new List<EnrollmentEvent>();
|
||||
long seq = 1;
|
||||
for (int b = 0; b < offsetsSeconds.Length; b++)
|
||||
{
|
||||
var receivedAt = T0.AddMinutes(b * 5);
|
||||
for (int i = 0; i < 5; i++)
|
||||
events.Add(MakeEvent(seq++, receivedAt, offsetsSeconds[b] + (i - 2)));
|
||||
}
|
||||
return events;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// One SentAt-carrying upload batch per frame offset: SentAt = ReceivedAt + frameOffset
|
||||
/// (the P14 direct measurement), event timestamps default to healthy in-batch jitter but
|
||||
/// can be overridden per batch to simulate spool spreads or backlogs.
|
||||
/// </summary>
|
||||
private static List<EnrollmentEvent> SentAtBatches(
|
||||
double[] frameOffsetsSeconds,
|
||||
Func<int, double[]>? eventOffsetsForBatch = null,
|
||||
string source = "DecisionEngine")
|
||||
{
|
||||
var events = new List<EnrollmentEvent>();
|
||||
long seq = 1;
|
||||
for (int b = 0; b < frameOffsetsSeconds.Length; b++)
|
||||
{
|
||||
var receivedAt = T0.AddMinutes(b * 5);
|
||||
var sentAt = receivedAt.AddSeconds(frameOffsetsSeconds[b]);
|
||||
var offsets = eventOffsetsForBatch?.Invoke(b) ?? new double[] { -2, -1, 0, 1, 2 };
|
||||
foreach (var offset in offsets)
|
||||
{
|
||||
var evt = MakeEvent(seq++, receivedAt, offset, source);
|
||||
evt.SentAt = sentAt;
|
||||
events.Add(evt);
|
||||
}
|
||||
}
|
||||
return events;
|
||||
}
|
||||
|
||||
private static EnrollmentEvent MakeEvent(long sequence, DateTime receivedAt, double offsetSeconds,
|
||||
string source = "DecisionEngine") => new()
|
||||
{
|
||||
EventId = Guid.NewGuid().ToString(),
|
||||
TenantId = TenantId,
|
||||
SessionId = SessionId,
|
||||
EventType = "status_update",
|
||||
Source = source,
|
||||
Timestamp = receivedAt.AddSeconds(offsetSeconds),
|
||||
ReceivedAt = receivedAt,
|
||||
Sequence = sequence,
|
||||
Data = new Dictionary<string, object>(),
|
||||
};
|
||||
|
||||
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<RuleEngineClockSkewTests>.Instance);
|
||||
|
||||
return await engine.AnalyzeSessionAsync(TenantId, SessionId);
|
||||
}
|
||||
}
|
||||
@@ -270,6 +270,59 @@ public class RuleEngineDryRunTests
|
||||
Assert.Contains(DryRunAnalyzeRuleFunction.ValidateDraftRule(rule), e => e.Contains("joinField"));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Validate_ClockSkewMissingOrUnknownMetric_Error()
|
||||
{
|
||||
var rule = MakeRule();
|
||||
rule.Conditions[0].Source = "clock_skew";
|
||||
rule.Conditions[0].SkewMetric = null;
|
||||
rule.Conditions[0].Operator = "gte";
|
||||
rule.Conditions[0].Value = "300";
|
||||
Assert.Contains(DryRunAnalyzeRuleFunction.ValidateDraftRule(rule), e => e.Contains("skewMetric"));
|
||||
|
||||
rule.Conditions[0].SkewMetric = "drift"; // not a known metric
|
||||
Assert.Contains(DryRunAnalyzeRuleFunction.ValidateDraftRule(rule), e => e.Contains("skewMetric"));
|
||||
}
|
||||
|
||||
[Theory]
|
||||
[InlineData("lt")]
|
||||
[InlineData("equals")]
|
||||
public void Validate_ClockSkewUnsupportedOperator_Error(string op)
|
||||
{
|
||||
var rule = MakeRule();
|
||||
rule.Conditions[0].Source = "clock_skew";
|
||||
rule.Conditions[0].SkewMetric = "clock_jump";
|
||||
rule.Conditions[0].Operator = op;
|
||||
rule.Conditions[0].Value = "300";
|
||||
Assert.Contains(DryRunAnalyzeRuleFunction.ValidateDraftRule(rule), e => e.Contains("only gt/gte"));
|
||||
}
|
||||
|
||||
[Theory]
|
||||
[InlineData("")]
|
||||
[InlineData("abc")]
|
||||
[InlineData("-300")]
|
||||
[InlineData("0")]
|
||||
public void Validate_ClockSkewNonPositiveThreshold_Error(string value)
|
||||
{
|
||||
var rule = MakeRule();
|
||||
rule.Conditions[0].Source = "clock_skew";
|
||||
rule.Conditions[0].SkewMetric = "sustained_offset";
|
||||
rule.Conditions[0].Operator = "gte";
|
||||
rule.Conditions[0].Value = value;
|
||||
Assert.Contains(DryRunAnalyzeRuleFunction.ValidateDraftRule(rule), e => e.Contains("positive numeric value"));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Validate_ClockSkewValidCondition_NoErrors()
|
||||
{
|
||||
var rule = MakeRule();
|
||||
rule.Conditions[0].Source = "clock_skew";
|
||||
rule.Conditions[0].SkewMetric = "clock_jump";
|
||||
rule.Conditions[0].Operator = "gte";
|
||||
rule.Conditions[0].Value = "300";
|
||||
Assert.Empty(DryRunAnalyzeRuleFunction.ValidateDraftRule(rule));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Validate_InvalidRegex_Error()
|
||||
{
|
||||
|
||||
+4
-1
@@ -131,9 +131,12 @@ namespace AutopilotMonitor.Functions.DataAccess.TableStorage
|
||||
earliestEventTimestamp, latestEventTimestamp, currentPhase,
|
||||
platformScriptIncrement, remediationScriptIncrement, rebootIncrement);
|
||||
|
||||
public Task ReconcileSessionCountersAsync(string tenantId, string sessionId)
|
||||
public Task<SessionSkewScan?> ReconcileSessionCountersAsync(string tenantId, string sessionId)
|
||||
=> _storage.ReconcileSessionCountersAsync(tenantId, sessionId);
|
||||
|
||||
public Task<Dictionary<string, int>> GetImeOffsetOriginHistogramAsync(string tenantId, string sessionId, int maxRows = 500)
|
||||
=> _storage.GetImeOffsetOriginHistogramAsync(tenantId, sessionId, maxRows);
|
||||
|
||||
public Task UpdateSessionDiagnosticsBlobAsync(
|
||||
string tenantId, string sessionId, string blobName, string? destination = null)
|
||||
=> _storage.UpdateSessionDiagnosticsBlobAsync(tenantId, sessionId, blobName, destination);
|
||||
|
||||
@@ -606,16 +606,14 @@ namespace AutopilotMonitor.Functions.Functions.Apps
|
||||
return date.AddDays(-diff);
|
||||
}
|
||||
|
||||
// Internal so AppVersionRegressionRadar shares the same nearest-rank convention
|
||||
// (a third percentile implementation would invite subtle median drift).
|
||||
// Internal so AppVersionRegressionRadar shares the same nearest-rank convention.
|
||||
// Thin delegation onto the single shared implementation (PercentileMath) — parallel
|
||||
// implementations would invite subtle median drift.
|
||||
internal static int Percentile(List<int> values, double percentile)
|
||||
{
|
||||
if (values.Count == 0) return 0;
|
||||
var sorted = values.OrderBy(v => v).ToList();
|
||||
var rank = (int)Math.Ceiling(percentile * sorted.Count) - 1;
|
||||
if (rank < 0) rank = 0;
|
||||
if (rank >= sorted.Count) rank = sorted.Count - 1;
|
||||
return sorted[rank];
|
||||
var sorted = values.Select(v => (double)v).OrderBy(v => v).ToList();
|
||||
return (int)Helpers.PercentileMath.Percentile(sorted, percentile);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
@@ -221,10 +221,17 @@ namespace AutopilotMonitor.Functions.Functions.Ingest
|
||||
// EventIngestProcessor, saving one Sessions point-read per batch.
|
||||
var preFetchedStatus = TryReadSessionStatus(guardSessionRow);
|
||||
|
||||
// P14: device-clock send time of this upload (one value per request). Separates
|
||||
// spool delay from device-vs-server clock offset downstream; absent/garbage → null.
|
||||
var sentAtHeader = req.Headers.Contains("X-Send-Time-Utc")
|
||||
? req.Headers.GetValues("X-Send-Time-Utc").FirstOrDefault()
|
||||
: null;
|
||||
var sentAt = ParseSendTimeHeader(sentAtHeader);
|
||||
|
||||
// Partition + persist. Events are routed through EventIngestProcessor which runs the
|
||||
// full pipeline (rule engine / app-install aggregation / SignalR / webhooks / ...);
|
||||
// Signal + Transition go straight to their repositories.
|
||||
var outcome = await PersistItemsAsync(items, bodyTenantId, sessionId, validation, preFetchedStatus);
|
||||
var outcome = await PersistItemsAsync(items, bodyTenantId, sessionId, validation, preFetchedStatus, sentAt);
|
||||
|
||||
_logger.LogInformation(
|
||||
"IngestTelemetry: tenant={Tenant} session={Session} events={E} signals={S} transitions={T} unknown={U}",
|
||||
@@ -349,7 +356,8 @@ namespace AutopilotMonitor.Functions.Functions.Ingest
|
||||
string tenantId,
|
||||
string sessionId,
|
||||
SecurityValidationResult validation,
|
||||
SessionStatus? preFetchedStatus)
|
||||
SessionStatus? preFetchedStatus,
|
||||
DateTime? sentAt)
|
||||
{
|
||||
var events = new List<EnrollmentEvent>();
|
||||
var signals = new List<SignalRecord>();
|
||||
@@ -435,6 +443,7 @@ namespace AutopilotMonitor.Functions.Functions.Ingest
|
||||
SessionId = sessionId,
|
||||
TenantId = tenantId,
|
||||
Events = events,
|
||||
SentAt = sentAt,
|
||||
};
|
||||
var processed = await _eventProcessor.ProcessEventsAsync(eventRequest, validation, preFetchedStatus);
|
||||
|
||||
@@ -570,6 +579,29 @@ namespace AutopilotMonitor.Functions.Functions.Ingest
|
||||
return false;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Parses the <c>X-Send-Time-Utc</c> header (agent device-clock send time, ISO-8601
|
||||
/// round-trip). Returns null for absent/unparseable values and for anything before
|
||||
/// year 2000 — Table Storage rejects pre-1601 DateTimes outright, and a sub-2000
|
||||
/// value can only be garbage, never a measurable clock offset. Deliberately NO upper
|
||||
/// clamp: a future-dated send time IS the device-clock-error measurement this field
|
||||
/// exists to capture.
|
||||
/// </summary>
|
||||
internal static DateTime? ParseSendTimeHeader(string? headerValue)
|
||||
{
|
||||
if (string.IsNullOrWhiteSpace(headerValue)) return null;
|
||||
|
||||
if (!DateTimeOffset.TryParse(
|
||||
headerValue,
|
||||
System.Globalization.CultureInfo.InvariantCulture,
|
||||
System.Globalization.DateTimeStyles.RoundtripKind,
|
||||
out var parsed))
|
||||
return null;
|
||||
|
||||
var utc = parsed.UtcDateTime;
|
||||
return utc.Year >= 2000 ? utc : (DateTime?)null;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// PartitionKey convention is <c>{tenantId}_{sessionId}</c> — both GUIDs with dashes, so
|
||||
/// splitting on the single underscore between them is unambiguous. Returns false for any
|
||||
|
||||
@@ -178,9 +178,90 @@ namespace AutopilotMonitor.Functions.Functions.Ingest
|
||||
|
||||
await MaterializeEmergencyBreakArtifactsAsync(report, tenantId, _sessionRepo, _opsEventService, _logger);
|
||||
|
||||
var adminConfig = await _adminConfigService.GetConfigurationAsync();
|
||||
await MaterializeIntegrityMismatchAsync(
|
||||
report, tenantId, _opsEventService,
|
||||
adminConfig?.LatestAgentV2Version, adminConfig?.LatestAgentV2ExeSha256, _logger);
|
||||
|
||||
return req.CreateResponse(HttpStatusCode.OK);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Regex over OUR OWN report format (AgentRuntimeConfig.VerifyBinaryIntegrity):
|
||||
/// "... actual=<sha256>, expected=<sha256>". Parsed leniently — an unparseable
|
||||
/// message records rather than suppresses.
|
||||
/// </summary>
|
||||
private static readonly System.Text.RegularExpressions.Regex ActualHashRegex =
|
||||
new(@"actual=([0-9a-fA-F]{64})", System.Text.RegularExpressions.RegexOptions.Compiled);
|
||||
|
||||
/// <summary>
|
||||
/// Surfaces an <c>IntegrityCheckFailed</c> report as an <c>AgentBinaryIntegrityMismatch</c>
|
||||
/// ops event. Before 2026-08-20 this report went to App Insights only — session e9753578's
|
||||
/// agent reported a hash mismatch and no product surface showed it, which cost a day of
|
||||
/// mis-attributed root-causing.
|
||||
///
|
||||
/// <para>
|
||||
/// KNOWN, ACCEPTED RACE (must not spam the ops feed): around every release, agents compare
|
||||
/// against a hash snapshot that does not belong to their own binary — a freshly installed
|
||||
/// latest agent can receive the PREVIOUS release's hashes from the 5-minute
|
||||
/// AdminConfiguration cache (e9753578: genuine 1410 exe vs cached 1409 hash), and an
|
||||
/// older agent's next config fetch sees the NEW release's hash. Both self-heal via the
|
||||
/// forced self-update. Suppression, evaluated against the CURRENT config at receive time:
|
||||
/// the reported RUNNING hash equals the published exe (stale expectation), or the
|
||||
/// reporting agent's version is not the latest (update in flight). What remains — an agent
|
||||
/// claiming the latest version whose binary is NOT the published one — is the real signal:
|
||||
/// tamper, stale blob, or a build that never came from the release pipeline.
|
||||
/// </para>
|
||||
///
|
||||
/// <para>
|
||||
/// Ops event only, no timeline event: the report is about the BINARY, not the enrollment,
|
||||
/// and may arrive before the session is registered. No idempotency read: the agent-side
|
||||
/// trigger is single-shot per process. Best-effort — a failure here must never turn the
|
||||
/// always-200 channel into a retry loop.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
internal static async Task MaterializeIntegrityMismatchAsync(
|
||||
AgentErrorReport report,
|
||||
string tenantId,
|
||||
OpsEventService opsEventService,
|
||||
string? latestAgentVersion,
|
||||
string? latestAgentExeSha256,
|
||||
ILogger logger)
|
||||
{
|
||||
if (report.ErrorType != AgentErrorType.IntegrityCheckFailed)
|
||||
{
|
||||
return;
|
||||
}
|
||||
|
||||
try
|
||||
{
|
||||
// "2.0.1410+3b59dab2..." → "2.0.1410" (the manifest/AdminConfig carry no +commit).
|
||||
var reportedVersion = (report.AgentVersion ?? string.Empty).Split('+')[0];
|
||||
if (!string.IsNullOrEmpty(latestAgentVersion)
|
||||
&& !string.IsNullOrEmpty(reportedVersion)
|
||||
&& !string.Equals(reportedVersion, latestAgentVersion, StringComparison.OrdinalIgnoreCase))
|
||||
{
|
||||
return; // older agent vs newer release — the forced self-update heals this.
|
||||
}
|
||||
|
||||
var actualMatch = ActualHashRegex.Match(report.Message ?? string.Empty);
|
||||
if (actualMatch.Success
|
||||
&& !string.IsNullOrEmpty(latestAgentExeSha256)
|
||||
&& string.Equals(actualMatch.Groups[1].Value, latestAgentExeSha256, StringComparison.OrdinalIgnoreCase))
|
||||
{
|
||||
return; // the running binary IS the published one — the agent's expectation was stale.
|
||||
}
|
||||
|
||||
await opsEventService.RecordAgentBinaryIntegrityMismatchAsync(
|
||||
tenantId, report.SessionId, report.AgentVersion, report.Message ?? string.Empty);
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
logger.LogWarning(ex,
|
||||
"ReportAgentError: failed to record AgentBinaryIntegrityMismatch ops event for session {SessionId}", report.SessionId);
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Materializes the agent's silent 48h emergency break as (1) a timeline event so it shows
|
||||
/// in the session and the timeout classifier can see it, (2) the cross-session EventType
|
||||
|
||||
+18
-1
@@ -128,7 +128,12 @@ namespace AutopilotMonitor.Functions.Functions.Rules
|
||||
internal static readonly HashSet<string> KnownSources = new(StringComparer.Ordinal)
|
||||
{
|
||||
"event_type", "event_data", "event_data_array", "event_count",
|
||||
"phase_duration", "app_install_duration", "event_correlation",
|
||||
"phase_duration", "app_install_duration", "event_correlation", "clock_skew",
|
||||
};
|
||||
|
||||
internal static readonly HashSet<string> KnownSkewMetrics = new(StringComparer.Ordinal)
|
||||
{
|
||||
"clock_jump", "sustained_offset",
|
||||
};
|
||||
|
||||
internal static readonly HashSet<string> KnownOperators = new(StringComparer.OrdinalIgnoreCase)
|
||||
@@ -196,6 +201,18 @@ namespace AutopilotMonitor.Functions.Functions.Rules
|
||||
errors.Add($"{label}: event_correlation requires joinField");
|
||||
}
|
||||
|
||||
if (string.Equals(c.Source, "clock_skew", StringComparison.Ordinal))
|
||||
{
|
||||
if (string.IsNullOrWhiteSpace(c.SkewMetric) || !KnownSkewMetrics.Contains(c.SkewMetric))
|
||||
errors.Add($"{label}: clock_skew requires skewMetric (one of: {string.Join(", ", KnownSkewMetrics)})");
|
||||
if (!string.Equals(c.Operator, "gt", StringComparison.OrdinalIgnoreCase)
|
||||
&& !string.Equals(c.Operator, "gte", StringComparison.OrdinalIgnoreCase))
|
||||
errors.Add($"{label}: clock_skew supports only gt/gte (magnitude vs threshold)");
|
||||
if (!double.TryParse(c.Value, System.Globalization.NumberStyles.Float,
|
||||
System.Globalization.CultureInfo.InvariantCulture, out var skewThreshold) || skewThreshold <= 0)
|
||||
errors.Add($"{label}: clock_skew requires a positive numeric value (threshold in seconds)");
|
||||
}
|
||||
|
||||
if ((string.Equals(c.Operator, "regex", StringComparison.OrdinalIgnoreCase)
|
||||
|| string.Equals(c.Operator, "not_regex", StringComparison.OrdinalIgnoreCase))
|
||||
&& !string.IsNullOrEmpty(c.Value))
|
||||
|
||||
@@ -63,7 +63,7 @@ namespace AutopilotMonitor.Functions.Helpers
|
||||
private static readonly HashSet<string> KnownFieldKeys = new(StringComparer.OrdinalIgnoreCase)
|
||||
{
|
||||
"eventId", "sessionId", "tenantId", "eventType", "severity", "source", "phase",
|
||||
"phaseName", "timestamp", "receivedAt", "message", "sequence", "rowKey",
|
||||
"phaseName", "timestamp", "receivedAt", "sentAt", "message", "sequence", "rowKey",
|
||||
"originalTimestamp", "timestampClamped", "causedByTransitionStepIndex",
|
||||
"causedBySignalOrdinal", "data",
|
||||
};
|
||||
@@ -86,6 +86,7 @@ namespace AutopilotMonitor.Functions.Helpers
|
||||
if (fields.Contains("phaseName")) dict["phaseName"] = e.PhaseName;
|
||||
if (fields.Contains("timestamp")) dict["timestamp"] = e.Timestamp;
|
||||
if (fields.Contains("receivedAt")) dict["receivedAt"] = e.ReceivedAt;
|
||||
if (fields.Contains("sentAt")) dict["sentAt"] = e.SentAt;
|
||||
if (fields.Contains("message")) dict["message"] = e.Message;
|
||||
if (fields.Contains("sequence")) dict["sequence"] = e.Sequence;
|
||||
if (fields.Contains("rowKey")) dict["rowKey"] = e.RowKey;
|
||||
|
||||
@@ -0,0 +1,30 @@
|
||||
using System;
|
||||
using System.Collections.Generic;
|
||||
using System.Linq;
|
||||
|
||||
namespace AutopilotMonitor.Functions.Helpers
|
||||
{
|
||||
/// <summary>
|
||||
/// The single nearest-rank percentile implementation (rank = ceil(p·n) − 1, clamped).
|
||||
/// AppsAnalyticsHelper.Percentile and PlatformMetricsService.Percentile delegate here;
|
||||
/// keep it that way — parallel implementations invite subtle median drift between
|
||||
/// surfaces that report the "same" statistic.
|
||||
/// </summary>
|
||||
internal static class PercentileMath
|
||||
{
|
||||
/// <summary>Nearest-rank percentile over an ascending-sorted list.</summary>
|
||||
internal static double Percentile(IReadOnlyList<double> sortedValues, double percentile)
|
||||
{
|
||||
if (sortedValues.Count == 0) return 0;
|
||||
var rank = (int)Math.Ceiling(percentile * sortedValues.Count) - 1;
|
||||
return sortedValues[Math.Max(0, Math.Min(rank, sortedValues.Count - 1))];
|
||||
}
|
||||
|
||||
/// <summary>Median (p50) over unsorted values.</summary>
|
||||
internal static double Median(IEnumerable<double> values)
|
||||
{
|
||||
var sorted = values.OrderBy(v => v).ToList();
|
||||
return Percentile(sorted, 0.50);
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,107 @@
|
||||
using System;
|
||||
using System.Collections.Generic;
|
||||
using AutopilotMonitor.Functions.Helpers;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
|
||||
namespace AutopilotMonitor.Functions.Services
|
||||
{
|
||||
/// <summary>
|
||||
/// Regression tripwire for the agent's CMTrace time resolution (per-line self-anchoring,
|
||||
/// docs/agent/cmtrace-time-resolution.md). Runs once per session on the terminal ingest
|
||||
/// batch, over samples the counter reconcile collected in its existing partition scan.
|
||||
///
|
||||
/// Detection: diff = median(Δ_IME) − median(Δ_other), where Δ = ReceivedAt − OccurredUtc.
|
||||
/// Shared upload/spool latency is common-mode and cancels in the difference; a timezone
|
||||
/// mis-conversion shifts only the IME side and lands on the 15-minute offset grid.
|
||||
/// Replayed old log lines produce large OFF-grid deltas — the grid-residual test is what
|
||||
/// separates the two (field measurement 2026-08-20: without it, 48 instead of 26 true hits).
|
||||
///
|
||||
/// Goal state: this never fires. Any hit is either a case the per-line anchoring does not
|
||||
/// cover or a detector bug — both are actionable findings, never noise to tune away.
|
||||
/// </summary>
|
||||
internal static class CmTraceSkewTripwire
|
||||
{
|
||||
// Same grid the agent anchors on and the same residual tolerance as its own grid
|
||||
// guard (docs/agent/cmtrace-time-resolution.md) — keep these in lockstep with the
|
||||
// agent so a future anchoring change stays traceable to this detector.
|
||||
internal const int GridMinutes = 15;
|
||||
internal const double ResidualToleranceMinutes = 2.0;
|
||||
internal const int MinSamplesPerSide = 20;
|
||||
// ReceivedAt is stamped per upload batch, not per event; a side backed by fewer
|
||||
// distinct batches yields a batch-composition artifact, not a session property.
|
||||
internal const int MinDistinctBatchesPerSide = 3;
|
||||
|
||||
internal sealed class Result
|
||||
{
|
||||
public double MedianImeDeltaMinutes { get; set; }
|
||||
public double MedianOtherDeltaMinutes { get; set; }
|
||||
public double DiffMinutes { get; set; }
|
||||
public int GridSteps { get; set; }
|
||||
public double ResidualMinutes { get; set; }
|
||||
public int ImeSampleCount { get; set; }
|
||||
public int OtherSampleCount { get; set; }
|
||||
public int ImeBatchCount { get; set; }
|
||||
public int OtherBatchCount { get; set; }
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Pure detector: non-null exactly when the session shows a grid-aligned divergence
|
||||
/// between IME-derived and other event timestamps. All suppression inputs live in the
|
||||
/// scan itself so the decision is fully unit-testable.
|
||||
/// </summary>
|
||||
internal static Result? Evaluate(SessionSkewScan? scan)
|
||||
{
|
||||
if (scan == null)
|
||||
return null;
|
||||
if (scan.ImeDeltaMinutes.Count < MinSamplesPerSide || scan.OtherDeltaMinutes.Count < MinSamplesPerSide)
|
||||
return null;
|
||||
if (scan.ImeDistinctBatchCount < MinDistinctBatchesPerSide || scan.OtherDistinctBatchCount < MinDistinctBatchesPerSide)
|
||||
return null;
|
||||
|
||||
var medianIme = PercentileMath.Median(scan.ImeDeltaMinutes);
|
||||
var medianOther = PercentileMath.Median(scan.OtherDeltaMinutes);
|
||||
var diff = medianIme - medianOther;
|
||||
var steps = (int)Math.Round(diff / GridMinutes, MidpointRounding.AwayFromZero);
|
||||
var residual = Math.Abs(diff - steps * (double)GridMinutes);
|
||||
|
||||
if (Math.Abs(steps) < 1 || residual >= ResidualToleranceMinutes)
|
||||
return null;
|
||||
|
||||
return new Result
|
||||
{
|
||||
MedianImeDeltaMinutes = medianIme,
|
||||
MedianOtherDeltaMinutes = medianOther,
|
||||
DiffMinutes = diff,
|
||||
GridSteps = steps,
|
||||
ResidualMinutes = residual,
|
||||
ImeSampleCount = scan.ImeDeltaMinutes.Count,
|
||||
OtherSampleCount = scan.OtherDeltaMinutes.Count,
|
||||
ImeBatchCount = scan.ImeDistinctBatchCount,
|
||||
OtherBatchCount = scan.OtherDistinctBatchCount,
|
||||
};
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// True when the session's IME events are dominated by writer-declared ("bias")
|
||||
/// offsets — a bias offset comes verbatim from the log line's own zone marker and
|
||||
/// cannot be an anchoring regression, so a grid hit there is not ours to alarm on.
|
||||
/// measuredWriterOffsetMinutes is deliberately NOT consulted: the per-file
|
||||
/// observation sticks to a stale value after an era flip-back (monotonicity guard),
|
||||
/// making it non-authoritative for exactly the sessions this tripwire inspects.
|
||||
/// </summary>
|
||||
internal static bool IsBiasDominated(IReadOnlyDictionary<string, int>? originHistogram)
|
||||
{
|
||||
if (originHistogram == null || originHistogram.Count == 0)
|
||||
return false;
|
||||
|
||||
int total = 0, bias = 0;
|
||||
foreach (var kv in originHistogram)
|
||||
{
|
||||
total += kv.Value;
|
||||
if (string.Equals(kv.Key, "bias", StringComparison.OrdinalIgnoreCase))
|
||||
bias += kv.Value;
|
||||
}
|
||||
return total > 0 && bias * 2 >= total;
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -6,6 +6,7 @@ using AutopilotMonitor.Shared.DataAccess;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
using Microsoft.ApplicationInsights;
|
||||
using Microsoft.Azure.Functions.Worker;
|
||||
using Microsoft.Extensions.Configuration;
|
||||
using Microsoft.Extensions.Logging;
|
||||
|
||||
namespace AutopilotMonitor.Functions.Services
|
||||
@@ -44,6 +45,10 @@ namespace AutopilotMonitor.Functions.Services
|
||||
private readonly AutopilotMonitor.Functions.Services.Analyze.InterimTriggerRegistry _interimTriggerRegistry;
|
||||
private readonly IVulnerabilityCorrelateProducer _vulnProducer;
|
||||
private readonly Ime.IImeMsiArchiveProducer _imeMsiArchiveProducer;
|
||||
private readonly IConfiguration _configuration;
|
||||
|
||||
/// <summary>App setting kill switch: set to "true" to skip the CMTrace skew tripwire entirely. Fail-open — the tripwire only notifies, it never mutates data.</summary>
|
||||
internal const string CmTraceSkewTripwireKillSwitchSetting = "CmTraceSkewTripwireDisabled";
|
||||
|
||||
public EventIngestProcessor(
|
||||
ILogger<EventIngestProcessor> logger,
|
||||
@@ -60,7 +65,8 @@ namespace AutopilotMonitor.Functions.Services
|
||||
AutopilotMonitor.Functions.Services.Analyze.IAnalyzeOnEnrollmentEndProducer analyzeProducer,
|
||||
AutopilotMonitor.Functions.Services.Analyze.InterimTriggerRegistry interimTriggerRegistry,
|
||||
IVulnerabilityCorrelateProducer vulnProducer,
|
||||
Ime.IImeMsiArchiveProducer imeMsiArchiveProducer)
|
||||
Ime.IImeMsiArchiveProducer imeMsiArchiveProducer,
|
||||
IConfiguration configuration)
|
||||
{
|
||||
_logger = logger;
|
||||
_sessionRepo = sessionRepo;
|
||||
@@ -77,6 +83,7 @@ namespace AutopilotMonitor.Functions.Services
|
||||
_interimTriggerRegistry = interimTriggerRegistry;
|
||||
_vulnProducer = vulnProducer;
|
||||
_imeMsiArchiveProducer = imeMsiArchiveProducer;
|
||||
_configuration = configuration;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
@@ -106,7 +113,7 @@ namespace AutopilotMonitor.Functions.Services
|
||||
validation.RateLimitResult?.MaxRequests);
|
||||
|
||||
var receivedAt = DateTime.UtcNow;
|
||||
StampServerFields(request.Events, request.TenantId, request.SessionId, receivedAt);
|
||||
StampServerFields(request.Events, request.TenantId, request.SessionId, receivedAt, request.SentAt);
|
||||
SanitizeEventTimestamps(request.Events, receivedAt, _logger);
|
||||
|
||||
var storedEvents = await _sessionRepo.StoreEventsBatchAsync(request.Events);
|
||||
@@ -247,7 +254,17 @@ namespace AutopilotMonitor.Functions.Services
|
||||
// replays where UpdateSessionStatusAsync no-ops.
|
||||
// Idempotent (no-ops when already correct) and fail-soft.
|
||||
if (isTerminalBatch)
|
||||
await _sessionRepo.ReconcileSessionCountersAsync(request.TenantId, request.SessionId);
|
||||
{
|
||||
var skewScan = await _sessionRepo.ReconcileSessionCountersAsync(request.TenantId, request.SessionId);
|
||||
|
||||
// CMTrace time-skew tripwire (goal state: never fires). Gated on the actual
|
||||
// status transition so terminal-batch REPLAYS (statusTransitioned == false)
|
||||
// cannot re-emit — the reconcile above runs on replays by design, the
|
||||
// tripwire must not. Fail-soft: ingest stays a 200 no matter what.
|
||||
if (skewScan != null && (statusTransitioned || whiteGloveStatusTransitioned))
|
||||
await TryFireCmTraceSkewTripwireAsync(request.TenantId, request.SessionId,
|
||||
updatedSession?.AgentVersion, skewScan);
|
||||
}
|
||||
|
||||
// Auto-analyze fan-out: enqueue a queue message instead of running fire-and-forget
|
||||
// Task.Run inside the function. The previous in-function approach could be killed
|
||||
@@ -545,18 +562,83 @@ namespace AutopilotMonitor.Functions.Services
|
||||
System.Globalization.CultureInfo.InvariantCulture, out value);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// CMTrace time-skew regression tripwire. Evaluates the per-source timestamp-delta
|
||||
/// samples the counter reconcile collected and emits a CmTraceTimeSkewRegression ops
|
||||
/// event when the IME-derived events diverge from the other sources by a clean
|
||||
/// 15-minute-grid multiple (see <see cref="CmTraceSkewTripwire"/>). One extra bounded
|
||||
/// storage read happens ONLY on the suspicion path (≈ never): the sourceOffsetOrigin
|
||||
/// histogram that rules out writer-declared ("bias") offsets, which come verbatim
|
||||
/// from the log line and cannot be an anchoring regression.
|
||||
/// </summary>
|
||||
private async Task TryFireCmTraceSkewTripwireAsync(
|
||||
string tenantId, string sessionId, string? agentVersion, SessionSkewScan skewScan)
|
||||
{
|
||||
try
|
||||
{
|
||||
if (string.Equals(_configuration[CmTraceSkewTripwireKillSwitchSetting], "true", StringComparison.OrdinalIgnoreCase))
|
||||
return;
|
||||
|
||||
var result = CmTraceSkewTripwire.Evaluate(skewScan);
|
||||
if (result == null)
|
||||
return;
|
||||
|
||||
var histogram = await _sessionRepo.GetImeOffsetOriginHistogramAsync(tenantId, sessionId);
|
||||
if (CmTraceSkewTripwire.IsBiasDominated(histogram))
|
||||
{
|
||||
_logger.LogInformation(
|
||||
"CMTrace skew tripwire suppressed for session {SessionId}: grid divergence {DiffMinutes:+0.0;-0.0} min, but IME offsets are bias-dominated (writer-declared)",
|
||||
sessionId, result.DiffMinutes);
|
||||
return;
|
||||
}
|
||||
|
||||
var origins = string.Join(", ",
|
||||
histogram.OrderByDescending(kv => kv.Value).Select(kv => $"{kv.Key} {kv.Value}"));
|
||||
var message =
|
||||
$"IME-derived events skewed {result.DiffMinutes:+0.0;-0.0} min vs other sources " +
|
||||
$"({result.GridSteps}x15min grid, residual {result.ResidualMinutes:0.0} min; " +
|
||||
$"median dIME {result.MedianImeDeltaMinutes:0.0} / dOther {result.MedianOtherDeltaMinutes:0.0} min; " +
|
||||
$"{result.ImeSampleCount}/{result.OtherSampleCount} samples over {result.ImeBatchCount}/{result.OtherBatchCount} batches; " +
|
||||
$"origins: {(origins.Length > 0 ? origins : "none")})";
|
||||
|
||||
await _opsEventService.RecordCmTraceTimeSkewRegressionAsync(tenantId, sessionId, agentVersion, message, new
|
||||
{
|
||||
sessionId,
|
||||
agentVersion,
|
||||
diffMinutes = Math.Round(result.DiffMinutes, 2),
|
||||
gridSteps = result.GridSteps,
|
||||
residualMinutes = Math.Round(result.ResidualMinutes, 2),
|
||||
medianImeDeltaMinutes = Math.Round(result.MedianImeDeltaMinutes, 2),
|
||||
medianOtherDeltaMinutes = Math.Round(result.MedianOtherDeltaMinutes, 2),
|
||||
imeSampleCount = result.ImeSampleCount,
|
||||
otherSampleCount = result.OtherSampleCount,
|
||||
imeBatchCount = result.ImeBatchCount,
|
||||
otherBatchCount = result.OtherBatchCount,
|
||||
sourceOffsetOrigins = histogram,
|
||||
});
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.LogWarning(ex, "CMTrace skew tripwire failed for session {SessionId}", sessionId);
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Stamps authoritative server-side fields onto all events before storage.
|
||||
/// TenantId and SessionId always come from the validated request metadata,
|
||||
/// overriding any values the agent may have sent per-event.
|
||||
/// overriding any values the agent may have sent per-event. SentAt is the
|
||||
/// request-level device-clock send time (P14) — one value for every event of
|
||||
/// the batch, null for agents that pre-date the X-Send-Time-Utc header.
|
||||
/// Exposed as internal for unit testing.
|
||||
/// </summary>
|
||||
internal static void StampServerFields(
|
||||
List<EnrollmentEvent> events, string tenantId, string sessionId, DateTime receivedAt)
|
||||
List<EnrollmentEvent> events, string tenantId, string sessionId, DateTime receivedAt,
|
||||
DateTime? sentAt = null)
|
||||
{
|
||||
foreach (var evt in events)
|
||||
{
|
||||
evt.ReceivedAt = receivedAt;
|
||||
evt.SentAt = sentAt;
|
||||
evt.TenantId = tenantId;
|
||||
evt.SessionId = sessionId;
|
||||
}
|
||||
|
||||
@@ -608,6 +608,36 @@ namespace AutopilotMonitor.Functions.Services
|
||||
$"Agent emergency break on session {sessionId} (agent {agentVersion ?? "?"}): {message}",
|
||||
tenantId, "System.EmergencyChannel", new { sessionId, agentVersion });
|
||||
|
||||
/// <summary>
|
||||
/// An agent reported that its RUNNING exe's SHA-256 differs from the hash the backend
|
||||
/// advertises for its version — the binary in the field is not the published build
|
||||
/// (tamper, stale blob, or a build that never came from a committed tree). Session
|
||||
/// e9753578 (2026-08-20) carried exactly this report, but it landed only in App
|
||||
/// Insights and was invisible to every product surface while the field damage was
|
||||
/// mis-attributed to committed code for hours. Warning-tier so operators can wire a
|
||||
/// Telegram rule; the message carries both hashes verbatim.
|
||||
/// </summary>
|
||||
public Task RecordAgentBinaryIntegrityMismatchAsync(string tenantId, string? sessionId, string? agentVersion, string message)
|
||||
=> WriteAsync(OpsEventCategory.Agent, "AgentBinaryIntegrityMismatch", OpsEventSeverity.Warning,
|
||||
$"Agent binary integrity mismatch on session {sessionId ?? "?"} (agent {agentVersion ?? "?"}): {message}",
|
||||
tenantId, "System.EmergencyChannel", new { sessionId, agentVersion });
|
||||
|
||||
/// <summary>
|
||||
/// The CMTrace time-skew tripwire fired: a terminal session's IME-derived event
|
||||
/// timestamps diverge from its other events by a clean 15-minute-grid multiple —
|
||||
/// the signature of a timezone mis-conversion the per-line self-anchoring
|
||||
/// (docs/agent/cmtrace-time-resolution.md) failed to catch. Goal state: this event
|
||||
/// NEVER fires; any occurrence is a real anchoring regression or a detector bug,
|
||||
/// both actionable. Emitted by <see cref="EventIngestProcessor"/> once per session
|
||||
/// (gated on the terminal status transition). The message carries the full numbers
|
||||
/// so the event is verifiable without a portal round-trip.
|
||||
/// Dual-register per memory feedback_ops_event_types_dual_register.
|
||||
/// </summary>
|
||||
public Task RecordCmTraceTimeSkewRegressionAsync(string tenantId, string sessionId, string? agentVersion, string message, object details)
|
||||
=> WriteAsync(OpsEventCategory.Agent, "CmTraceTimeSkewRegression", OpsEventSeverity.Warning,
|
||||
$"CMTrace time-skew tripwire on session {sessionId} (agent {agentVersion ?? "?"}): {message}",
|
||||
tenantId, "System.Ingest", details);
|
||||
|
||||
public Task RecordExcessiveSessionEventsAsync(string tenantId, string sessionId, int eventCount, int threshold)
|
||||
=> WriteAsync(OpsEventCategory.Agent, "ExcessiveSessionEvents", OpsEventSeverity.Warning,
|
||||
$"Session {sessionId} has {eventCount} events (threshold {threshold}) — likely agent loop bug",
|
||||
|
||||
@@ -312,12 +312,9 @@ namespace AutopilotMonitor.Functions.Services
|
||||
};
|
||||
}
|
||||
|
||||
// Thin delegation onto the single shared nearest-rank implementation (PercentileMath).
|
||||
private static double Percentile(List<double> sortedValues, double percentile)
|
||||
{
|
||||
if (sortedValues.Count == 0) return 0;
|
||||
var index = (int)Math.Ceiling(percentile * sortedValues.Count) - 1;
|
||||
return sortedValues[Math.Max(0, Math.Min(index, sortedValues.Count - 1))];
|
||||
}
|
||||
=> Helpers.PercentileMath.Percentile(sortedValues, percentile);
|
||||
|
||||
// Payload getters live in AgentMetricsAggregation (shared with the efficiency
|
||||
// service); these thin wrappers keep the call sites above unchanged.
|
||||
|
||||
@@ -98,6 +98,9 @@ namespace AutopilotMonitor.Functions.Services
|
||||
case "event_correlation":
|
||||
return EvaluateEventCorrelationCondition(condition, events);
|
||||
|
||||
case "clock_skew":
|
||||
return EvaluateClockSkewCondition(condition, events);
|
||||
|
||||
default:
|
||||
return (false, "unknown source");
|
||||
}
|
||||
@@ -808,6 +811,209 @@ namespace AutopilotMonitor.Functions.Services
|
||||
return (false, "no app install duration matched");
|
||||
}
|
||||
|
||||
// ===== clock_skew constants =====
|
||||
// Named constants, deliberately NOT condition fields: promoting a constant to a field
|
||||
// later is non-breaking, the reverse is not.
|
||||
/// <summary>Frame windows (in upload batches) that must agree before/after a step for it to count as a clock jump.</summary>
|
||||
internal const int ClockSkewConfirmBatches = 3;
|
||||
/// <summary>Floor for the per-batch internal-spread cap, seconds.</summary>
|
||||
internal const double ClockSkewSpoolSpreadFloorSeconds = 60;
|
||||
/// <summary>Per-batch internal-spread cap as a fraction of the condition threshold.</summary>
|
||||
internal const double ClockSkewSpoolSpreadCapFraction = 0.5;
|
||||
/// <summary>Fraction of surviving batches that must sit near the overall median for a sustained-offset verdict.</summary>
|
||||
internal const double ClockSkewStableBatchFraction = 0.75;
|
||||
|
||||
/// <summary>
|
||||
/// Detects DEVICE clock problems from a per-upload-batch offset between the device's
|
||||
/// clock frame and the server's receive frame (seconds; healthy baseline ≈
|
||||
/// −upload-latency, i.e. a few seconds negative).
|
||||
/// skewMetric "clock_jump": a persistent step in the device's clock frame mid-session
|
||||
/// (time sync correcting a wrong RTC, Windows auto-timezone, manual change).
|
||||
/// skewMetric "sustained_offset": the whole session ran on a clock off by ≥ threshold
|
||||
/// — the during-enrollment complement of ANALYZE-DEV-007's one-shot NTP check.
|
||||
///
|
||||
/// Batch offset, two measurement paths (P14):
|
||||
/// - Events carrying SentAt (X-Send-Time-Utc header, one device-clock value per ingest
|
||||
/// request): offset = SentAt − ReceivedAt, a DIRECT frame-crossing measurement. No
|
||||
/// event timestamps involved → immune to spool backlog, CMTrace writer beliefs and
|
||||
/// clamping by construction, so no spread filter is needed and every batch counts.
|
||||
/// - Legacy batches (agents without the header): median of per-event Timestamp −
|
||||
/// ReceivedAt with a spread cap that drops replayed spool backlogs, excluding
|
||||
/// CMTrace-derived events (Source == "ImeLogTracker") — their Timestamp carries the
|
||||
/// log WRITER's timezone belief, so an anchoring regression must fire the
|
||||
/// operator-side CmTraceSkewTripwire, never this customer-facing rule.
|
||||
///
|
||||
/// Ordering key is Sequence, never Timestamp (see EvaluateAppInstallDurationCondition).
|
||||
/// The legacy path then inspects Timestamp AGAINST that Sequence order ON PURPOSE — a
|
||||
/// device-clock problem is precisely a Timestamp anomaly relative to the clock-immune
|
||||
/// Sequence/ReceivedAt frame. Timestamp is a MEASUREMENT here, never a sort key.
|
||||
/// </summary>
|
||||
private (bool matched, object evidence) EvaluateClockSkewCondition(RuleCondition condition, List<EnrollmentEvent> events)
|
||||
{
|
||||
var metric = condition.SkewMetric ?? string.Empty;
|
||||
if (!double.TryParse(condition.Value, System.Globalization.NumberStyles.Float,
|
||||
System.Globalization.CultureInfo.InvariantCulture, out var thresholdSeconds) || thresholdSeconds <= 0)
|
||||
return (false, "clock_skew requires a positive numeric value (threshold in seconds)");
|
||||
|
||||
var usable = events
|
||||
.Where(e => e.ReceivedAt.HasValue)
|
||||
.OrderBy(e => e.Sequence)
|
||||
.ToList();
|
||||
if (usable.Count == 0)
|
||||
return (false, "no events with a server receive frame");
|
||||
|
||||
// Group into upload batches (ReceivedAt is stamped once per ingest request). Legacy
|
||||
// rationale for the spread cap: a clock offset shifts a whole batch uniformly
|
||||
// (internal spread ≈ upload debounce, seconds); a spool-backlog batch spans the
|
||||
// offline period (spread = minutes–hours). Dropping wide-spread batches is what
|
||||
// makes replayed backlogs inert on the legacy path.
|
||||
var spreadCap = Math.Max(ClockSkewSpoolSpreadFloorSeconds, thresholdSeconds * ClockSkewSpoolSpreadCapFraction);
|
||||
var batches = new List<(double MedianOffsetSeconds, EnrollmentEvent FirstEvent)>();
|
||||
int usedSamples = 0;
|
||||
int sentAtBatchCount = 0;
|
||||
foreach (var batch in usable.GroupBy(e => e.ReceivedAt!.Value))
|
||||
{
|
||||
// P14 direct path — SentAt is request-level, so any event's value speaks for
|
||||
// the whole batch.
|
||||
var sentAt = batch.Select(e => e.SentAt).FirstOrDefault(s => s.HasValue);
|
||||
if (sentAt.HasValue)
|
||||
{
|
||||
sentAtBatchCount++;
|
||||
usedSamples += batch.Count();
|
||||
batches.Add(((sentAt.Value - batch.Key).TotalSeconds, batch.First()));
|
||||
continue;
|
||||
}
|
||||
|
||||
// Legacy path — see the method doc for the IME/clamped exclusions.
|
||||
var measurable = batch
|
||||
.Where(e => !e.TimestampClamped
|
||||
&& !string.Equals(e.Source, "ImeLogTracker", StringComparison.OrdinalIgnoreCase))
|
||||
.ToList();
|
||||
if (measurable.Count == 0)
|
||||
continue;
|
||||
|
||||
var offsets = measurable.Select(e => (e.Timestamp - batch.Key).TotalSeconds).OrderBy(v => v).ToList();
|
||||
if (offsets[offsets.Count - 1] - offsets[0] > spreadCap)
|
||||
continue;
|
||||
usedSamples += offsets.Count;
|
||||
batches.Add((Helpers.PercentileMath.Percentile(offsets, 0.50), measurable[0]));
|
||||
}
|
||||
|
||||
switch (metric)
|
||||
{
|
||||
case "sustained_offset":
|
||||
{
|
||||
if (batches.Count < 2)
|
||||
return (false, "insufficient upload batches for an offset measurement");
|
||||
|
||||
var batchMedians = batches.Select(b => b.MedianOffsetSeconds).ToList();
|
||||
var overall = Helpers.PercentileMath.Median(batchMedians);
|
||||
|
||||
// Constant offset, not drift chaos: most batches must individually sit near
|
||||
// the session median, otherwise no single "the clock was off by X" statement
|
||||
// is honest.
|
||||
var stable = batchMedians.Count(m => Math.Abs(m - overall) <= spreadCap);
|
||||
if (stable < Math.Max(2, (int)Math.Ceiling(batchMedians.Count * ClockSkewStableBatchFraction)))
|
||||
return (false, "batch offsets too unstable for a sustained-offset verdict");
|
||||
|
||||
if (!CompareClockSkewThreshold(Math.Abs(overall), condition.Operator, thresholdSeconds))
|
||||
return (false, $"sustained offset {overall:0} s below threshold");
|
||||
|
||||
var first = batches[0].FirstEvent;
|
||||
var offsetMinutes = Math.Round(overall / 60.0, 1);
|
||||
var direction = overall > 0 ? "ahead" : "behind";
|
||||
return (true, new Dictionary<string, object>
|
||||
{
|
||||
// field/value pair drives {{skewSummary}} template interpolation
|
||||
// (lib/interpolateRuleTemplate.ts resolves field→value first).
|
||||
["field"] = "skewSummary",
|
||||
["value"] = $"clock ran {Math.Abs(offsetMinutes)} min {direction} of server time throughout the session",
|
||||
["offsetSeconds"] = Math.Round(overall, 0),
|
||||
["offsetMinutes"] = offsetMinutes,
|
||||
["direction"] = direction,
|
||||
["eventId"] = first.EventId,
|
||||
["sequence"] = first.Sequence,
|
||||
["timestamp"] = first.Timestamp,
|
||||
["sampleCount"] = usedSamples,
|
||||
["batchCount"] = batches.Count,
|
||||
["sentAtBatchCount"] = sentAtBatchCount,
|
||||
});
|
||||
}
|
||||
|
||||
case "clock_jump":
|
||||
{
|
||||
const int w = ClockSkewConfirmBatches;
|
||||
if (batches.Count < 2 * w)
|
||||
return (false, "insufficient upload batches for a frame comparison");
|
||||
|
||||
var medians = batches.Select(b => b.MedianOffsetSeconds).ToList();
|
||||
(int Index, double Pre, double Post, double Jump)? best = null;
|
||||
for (int j = w - 1; j <= batches.Count - 1 - w; j++)
|
||||
{
|
||||
var preWindow = medians.Skip(j - w + 1).Take(w).ToList();
|
||||
var postWindow = medians.Skip(j + 1).Take(w).ToList();
|
||||
|
||||
// Both comparison windows must be flat plateaus: a genuine clock change
|
||||
// is a step between two stable frames, while a gradually draining spool
|
||||
// backlog produces a RAMP of batch medians — sloping windows would let
|
||||
// any pre/post pair straddling the ramp fake a step.
|
||||
if (preWindow.Max() - preWindow.Min() > spreadCap || postWindow.Max() - postWindow.Min() > spreadCap)
|
||||
continue;
|
||||
|
||||
var pre = Helpers.PercentileMath.Median(preWindow);
|
||||
var post = Helpers.PercentileMath.Median(postWindow);
|
||||
var jump = post - pre;
|
||||
if (CompareClockSkewThreshold(Math.Abs(jump), condition.Operator, thresholdSeconds)
|
||||
&& (best == null || Math.Abs(jump) > Math.Abs(best.Value.Jump)))
|
||||
best = (j, pre, post, jump);
|
||||
}
|
||||
if (best == null)
|
||||
return (false, "no persistent clock step");
|
||||
|
||||
// End-state persistence: a transient excursion that returns to the original
|
||||
// frame (spool backlog draining, historic replay) must stay silent; a genuine
|
||||
// clock change — including "wrong clock corrected by time sync mid-session" —
|
||||
// persists to session end, because the corrected frame IS the change.
|
||||
var tail = Helpers.PercentileMath.Median(medians.Skip(medians.Count - w).Take(w));
|
||||
var tailShift = tail - best.Value.Pre;
|
||||
if (Math.Abs(tailShift) < thresholdSeconds || Math.Sign(tailShift) != Math.Sign(best.Value.Jump))
|
||||
return (false, "transient timestamp excursion, not a sustained clock change");
|
||||
|
||||
var boundary = batches[best.Value.Index + 1].FirstEvent;
|
||||
var jumpMinutes = Math.Round(best.Value.Jump / 60.0, 1);
|
||||
var direction = best.Value.Jump > 0 ? "forward" : "backward";
|
||||
return (true, new Dictionary<string, object>
|
||||
{
|
||||
// field/value pair drives {{skewSummary}} template interpolation
|
||||
// (lib/interpolateRuleTemplate.ts resolves field→value first).
|
||||
["field"] = "skewSummary",
|
||||
["value"] = $"clock jumped {Math.Abs(jumpMinutes)} min {direction} mid-session",
|
||||
["jumpSeconds"] = Math.Round(best.Value.Jump, 0),
|
||||
["jumpMinutes"] = jumpMinutes,
|
||||
["direction"] = direction,
|
||||
["beforeOffsetMinutes"] = Math.Round(best.Value.Pre / 60.0, 1),
|
||||
["afterOffsetMinutes"] = Math.Round(best.Value.Post / 60.0, 1),
|
||||
["eventId"] = boundary.EventId,
|
||||
["sequence"] = boundary.Sequence,
|
||||
["timestamp"] = boundary.Timestamp,
|
||||
["eventType"] = boundary.EventType,
|
||||
["sampleCount"] = usedSamples,
|
||||
["batchCount"] = batches.Count,
|
||||
["sentAtBatchCount"] = sentAtBatchCount,
|
||||
});
|
||||
}
|
||||
|
||||
default:
|
||||
return (false, $"unknown skewMetric '{metric}' (expected clock_jump or sustained_offset)");
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>gt/gte magnitude comparison for clock_skew; unknown operators behave as gte (validation rejects them upstream).</summary>
|
||||
private static bool CompareClockSkewThreshold(double magnitude, string? op, double thresholdSeconds)
|
||||
=> string.Equals(op, "gt", StringComparison.OrdinalIgnoreCase)
|
||||
? magnitude > thresholdSeconds
|
||||
: magnitude >= thresholdSeconds;
|
||||
|
||||
/// <summary>
|
||||
/// Generic event correlation: finds pairs of events (A before B) sharing
|
||||
/// the same value in a join field, with optional filters on each event
|
||||
|
||||
@@ -815,6 +815,11 @@ namespace AutopilotMonitor.Functions.Services
|
||||
["TimestampClamped"] = evt.TimestampClamped
|
||||
};
|
||||
|
||||
// P14: request-level device-clock send time; column stays unset for
|
||||
// events from agents that pre-date the X-Send-Time-Utc header.
|
||||
if (evt.SentAt.HasValue)
|
||||
entity["SentAt"] = EnsureUtc(evt.SentAt.Value);
|
||||
|
||||
if (evt.OriginalTimestamp.HasValue)
|
||||
entity["OriginalTimestamp"] = EnsureUtc(evt.OriginalTimestamp.Value);
|
||||
|
||||
@@ -912,6 +917,10 @@ namespace AutopilotMonitor.Functions.Services
|
||||
["TimestampClamped"] = evt.TimestampClamped
|
||||
};
|
||||
|
||||
// P14: see StoreEventAsync.
|
||||
if (evt.SentAt.HasValue)
|
||||
entity["SentAt"] = EnsureUtc(evt.SentAt.Value);
|
||||
|
||||
if (evt.OriginalTimestamp.HasValue)
|
||||
entity["OriginalTimestamp"] = EnsureUtc(evt.OriginalTimestamp.Value);
|
||||
|
||||
@@ -2418,17 +2427,20 @@ namespace AutopilotMonitor.Functions.Services
|
||||
/// are left untouched rather than being zeroed. Idempotent: no-ops when the row is
|
||||
/// already correct. PlatformScriptCount/RemediationScriptCount stay increment-only (their
|
||||
/// drift is bounded and they feed no enforcement heuristics; EventCount does).
|
||||
/// Returns the skew-scan samples collected during the authoritative count's partition
|
||||
/// scan (CmTraceSkewTripwire input), or null when the scan itself failed — the counter
|
||||
/// reconcile outcome does not affect the returned scan.
|
||||
/// </summary>
|
||||
public async Task ReconcileSessionCountersAsync(string tenantId, string sessionId)
|
||||
public async Task<SessionSkewScan?> ReconcileSessionCountersAsync(string tenantId, string sessionId)
|
||||
{
|
||||
SecurityValidator.EnsureValidGuid(tenantId, nameof(tenantId));
|
||||
SecurityValidator.EnsureValidGuid(sessionId, nameof(sessionId));
|
||||
|
||||
var authoritative = await CountSessionEventRowsAsync(tenantId, sessionId);
|
||||
if (!authoritative.HasValue)
|
||||
return; // storage error — keep the incremental live values, do not zero them
|
||||
return null; // storage error — keep the incremental live values, do not zero them
|
||||
|
||||
var (totalEvents, rebootEvents) = authoritative.Value;
|
||||
var (totalEvents, rebootEvents, skewScan) = authoritative.Value;
|
||||
|
||||
const int maxRetries = 5;
|
||||
int retryCount = 0;
|
||||
@@ -2440,7 +2452,7 @@ namespace AutopilotMonitor.Functions.Services
|
||||
var tableClient = _tableServiceClient.GetTableClient(Constants.TableNames.Sessions);
|
||||
var entityResponse = await tableClient.GetEntityIfExistsAsync<TableEntity>(tenantId, sessionId);
|
||||
if (!entityResponse.HasValue)
|
||||
return;
|
||||
return skewScan;
|
||||
var entity = entityResponse.Value!;
|
||||
|
||||
// No-op when already correct — avoids a needless write + index sync on the
|
||||
@@ -2459,7 +2471,7 @@ namespace AutopilotMonitor.Functions.Services
|
||||
drifted = true;
|
||||
}
|
||||
if (!drifted)
|
||||
return;
|
||||
return skewScan;
|
||||
|
||||
var currentStartedAt = entity.GetDateTimeOffset("StartedAt")?.UtcDateTime ?? DateTime.MaxValue;
|
||||
|
||||
@@ -2468,7 +2480,7 @@ namespace AutopilotMonitor.Functions.Services
|
||||
// Dual-write: keep SessionsIndex in sync (merge — no StartedAt shift here).
|
||||
await SyncSessionIndexAsync(tenantId, sessionId, entity, update, currentStartedAt, null);
|
||||
|
||||
return;
|
||||
return skewScan;
|
||||
}
|
||||
catch (Azure.RequestFailedException ex) when (ex.Status == 412)
|
||||
{
|
||||
@@ -2476,7 +2488,7 @@ namespace AutopilotMonitor.Functions.Services
|
||||
if (retryCount >= maxRetries)
|
||||
{
|
||||
_logger.LogWarning($"Failed to reconcile session counters for session {sessionId} after {maxRetries} retries due to ETag conflicts");
|
||||
return;
|
||||
return skewScan;
|
||||
}
|
||||
var baseDelay = 50 * (int)Math.Pow(2, retryCount - 1);
|
||||
await Task.Delay(baseDelay + Random.Shared.Next(0, baseDelay));
|
||||
@@ -2484,9 +2496,11 @@ namespace AutopilotMonitor.Functions.Services
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.LogError(ex, $"Failed to reconcile session counters for session {sessionId}");
|
||||
return;
|
||||
return skewScan;
|
||||
}
|
||||
}
|
||||
|
||||
return skewScan;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
@@ -3083,6 +3097,7 @@ namespace AutopilotMonitor.Functions.Services
|
||||
Data = DeserializeEventData(entity.GetString("DataJson")),
|
||||
RowKey = entity.RowKey,
|
||||
ReceivedAt = entity.GetDateTimeOffset("ReceivedAt")?.UtcDateTime,
|
||||
SentAt = entity.GetDateTimeOffset("SentAt")?.UtcDateTime,
|
||||
OriginalTimestamp = entity.GetDateTimeOffset("OriginalTimestamp")?.UtcDateTime,
|
||||
TimestampClamped = entity.GetBoolean("TimestampClamped") ?? false,
|
||||
// Codex follow-up #3 — forward-link columns (nullable for legacy rows).
|
||||
@@ -3287,9 +3302,10 @@ namespace AutopilotMonitor.Functions.Services
|
||||
/// and a unique RowKey per event, so the number of stored rows equals the true distinct
|
||||
/// count — making this an idempotent, retry-immune authoritative count (used to reconcile
|
||||
/// EventCount + RebootCount at the terminal transition). Single partition scan with a
|
||||
/// RowKey+EventType projection so both counts cost one query.
|
||||
/// slim projection so both counts cost one query. The CmTraceSkewTripwire's per-source
|
||||
/// timestamp-delta samples piggyback on the same enumeration (zero extra reads).
|
||||
/// </summary>
|
||||
private async Task<(int Total, int Reboots)?> CountSessionEventRowsAsync(string tenantId, string sessionId)
|
||||
private async Task<(int Total, int Reboots, SessionSkewScan Skew)?> CountSessionEventRowsAsync(string tenantId, string sessionId)
|
||||
{
|
||||
try
|
||||
{
|
||||
@@ -3297,17 +3313,38 @@ namespace AutopilotMonitor.Functions.Services
|
||||
var partitionKey = $"{tenantId}_{sessionId}";
|
||||
var query = tableClient.QueryAsync<TableEntity>(
|
||||
filter: $"PartitionKey eq '{partitionKey}'",
|
||||
select: new[] { "RowKey", "EventType" }
|
||||
select: new[] { "RowKey", "EventType", "Source", "ReceivedAt", BusinessTimestamp.OccurredUtcColumn, "TimestampClamped" }
|
||||
);
|
||||
|
||||
int total = 0, reboots = 0;
|
||||
var skew = new SessionSkewScan();
|
||||
var imeBatches = new HashSet<DateTime>();
|
||||
var otherBatches = new HashSet<DateTime>();
|
||||
const int maxSkewSamplesPerSide = 20_000;
|
||||
await foreach (var entity in query)
|
||||
{
|
||||
total++;
|
||||
if (entity.GetString("EventType") == Constants.EventTypes.SystemRebootDetected)
|
||||
reboots++;
|
||||
|
||||
// Skew sample. Clamped events carry a server-substituted OccurredUtc
|
||||
// (Δ ≈ 0) and would dilute the medians; legacy rows without ReceivedAt
|
||||
// have no server frame at all — both are skipped, never zero-filled.
|
||||
if (entity.GetBoolean("TimestampClamped") == true)
|
||||
continue;
|
||||
var receivedAt = entity.GetDateTimeOffset("ReceivedAt")?.UtcDateTime;
|
||||
var occurredAt = ResolveEventTimestampOrNull(entity);
|
||||
if (!receivedAt.HasValue || !occurredAt.HasValue)
|
||||
continue;
|
||||
var isIme = string.Equals(entity.GetString("Source"), "ImeLogTracker", StringComparison.OrdinalIgnoreCase);
|
||||
var side = isIme ? skew.ImeDeltaMinutes : skew.OtherDeltaMinutes;
|
||||
if (side.Count < maxSkewSamplesPerSide)
|
||||
side.Add((receivedAt.Value - occurredAt.Value).TotalMinutes);
|
||||
(isIme ? imeBatches : otherBatches).Add(receivedAt.Value);
|
||||
}
|
||||
return (total, reboots);
|
||||
skew.ImeDistinctBatchCount = imeBatches.Count;
|
||||
skew.OtherDistinctBatchCount = otherBatches.Count;
|
||||
return (total, reboots, skew);
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
@@ -3316,6 +3353,49 @@ namespace AutopilotMonitor.Functions.Services
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Bounded histogram of the <c>sourceOffsetOrigin</c> provenance values ("bias",
|
||||
/// "line-anchored", "reader-zone-fallback", retired "calibrated") over a session's
|
||||
/// IME-derived events. Only read on the CmTraceSkewTripwire suspicion path (≈ never),
|
||||
/// so the row cap bounds the worst case rather than tuning the common one. Fail-soft:
|
||||
/// storage errors return an empty map, which the caller treats as "not bias-dominated"
|
||||
/// — the tripwire fails open toward reporting.
|
||||
/// </summary>
|
||||
public async Task<Dictionary<string, int>> GetImeOffsetOriginHistogramAsync(string tenantId, string sessionId, int maxRows = 500)
|
||||
{
|
||||
SecurityValidator.EnsureValidGuid(tenantId, nameof(tenantId));
|
||||
SecurityValidator.EnsureValidGuid(sessionId, nameof(sessionId));
|
||||
|
||||
var histogram = new Dictionary<string, int>(StringComparer.OrdinalIgnoreCase);
|
||||
try
|
||||
{
|
||||
var tableClient = _tableServiceClient.GetTableClient(Constants.TableNames.Events);
|
||||
var partitionKey = $"{tenantId}_{sessionId}";
|
||||
var query = tableClient.QueryAsync<TableEntity>(
|
||||
filter: $"PartitionKey eq '{partitionKey}' and Source eq 'ImeLogTracker'",
|
||||
select: new[] { "RowKey", "DataJson" });
|
||||
|
||||
int rows = 0;
|
||||
await foreach (var entity in query)
|
||||
{
|
||||
if (++rows > maxRows)
|
||||
break;
|
||||
var data = DeserializeEventData(entity.GetString("DataJson"));
|
||||
if (data != null && data.TryGetValue("sourceOffsetOrigin", out var origin))
|
||||
{
|
||||
var key = origin?.ToString();
|
||||
if (!string.IsNullOrEmpty(key))
|
||||
histogram[key!] = histogram.TryGetValue(key!, out var count) ? count + 1 : 1;
|
||||
}
|
||||
}
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.LogDebug(ex, $"Could not read IME offset-origin histogram for session {sessionId}");
|
||||
}
|
||||
return histogram;
|
||||
}
|
||||
|
||||
#region IME Version History
|
||||
|
||||
/// <summary>
|
||||
|
||||
@@ -361,6 +361,41 @@ describe('analyze semantic lint', () => {
|
||||
expect(errors(validateRuleDraft(corr).findings).some((m) => m.includes('joinField'))).toBe(true);
|
||||
});
|
||||
|
||||
it('clock_skew: missing/unknown skewMetric, bad operator, bad threshold are errors; {{skewSummary}} resolves', () => {
|
||||
const missingMetric = validAnalyze();
|
||||
(missingMetric.conditions as Array<Record<string, unknown>>)[0] = {
|
||||
signal: 'clock_jump', source: 'clock_skew', operator: 'gte', value: '300', required: true,
|
||||
};
|
||||
expect(errors(validateRuleDraft(missingMetric).findings).some((m) => m.includes('skewMetric'))).toBe(true);
|
||||
|
||||
const badOperator = validAnalyze();
|
||||
(badOperator.conditions as Array<Record<string, unknown>>)[0] = {
|
||||
signal: 'clock_jump', source: 'clock_skew', skewMetric: 'clock_jump', operator: 'lt', value: '300', required: true,
|
||||
};
|
||||
expect(errors(validateRuleDraft(badOperator).findings).some((m) => m.includes('gt/gte'))).toBe(true);
|
||||
|
||||
const badThreshold = validAnalyze();
|
||||
(badThreshold.conditions as Array<Record<string, unknown>>)[0] = {
|
||||
signal: 'clock_jump', source: 'clock_skew', skewMetric: 'clock_jump', operator: 'gte', value: '-5', required: true,
|
||||
};
|
||||
expect(errors(validateRuleDraft(badThreshold).findings).some((m) => m.includes('positive numeric'))).toBe(true);
|
||||
|
||||
const noisy = validAnalyze();
|
||||
(noisy.conditions as Array<Record<string, unknown>>)[0] = {
|
||||
signal: 'clock_jump', source: 'clock_skew', skewMetric: 'clock_jump', operator: 'gte', value: '30', required: true,
|
||||
};
|
||||
expect(warnings(validateRuleDraft(noisy).findings).some((m) => m.includes('upload-latency noise'))).toBe(true);
|
||||
|
||||
const good = validAnalyze();
|
||||
(good.conditions as Array<Record<string, unknown>>)[0] = {
|
||||
signal: 'clock_jump', source: 'clock_skew', skewMetric: 'clock_jump', operator: 'gte', value: '300', required: true,
|
||||
};
|
||||
good.explanation = 'This device {{skewSummary}}.';
|
||||
const r = validateRuleDraft(good);
|
||||
expect(errors(r.findings)).toEqual([]);
|
||||
expect(warnings(r.findings).filter((m) => m.includes('{{'))).toEqual([]);
|
||||
});
|
||||
|
||||
it('invalid regex is an error; unanchored not_regex warns', () => {
|
||||
const bad = validAnalyze();
|
||||
(bad.conditions as Array<Record<string, unknown>>)[0] = {
|
||||
|
||||
@@ -165,6 +165,13 @@ export const RULE_AUTHORING_GUIDE = {
|
||||
'Join two event types over a shared field: eventType + correlateEventType + joinField, ' +
|
||||
'optional timeWindowSeconds, optional eventAFilterField/-Operator/-Value to pre-filter the ' +
|
||||
'first event, optional dataField+operator+value tested on the correlated pair.',
|
||||
clock_skew:
|
||||
'Device-clock check against the server receive frame: skewMetric=clock_jump (persistent ' +
|
||||
'mid-session step) or sustained_offset (whole session off by >= value). value = threshold ' +
|
||||
'seconds, operator gt/gte on the magnitude. No eventType/dataField; IME-log-derived events ' +
|
||||
'are excluded from the measurement. Batches from agents that send X-Send-Time-Utc are ' +
|
||||
'measured directly from the send time (spool-immune; evidence sentAtBatchCount counts them), ' +
|
||||
'older agents fall back to per-event timestamp medians.',
|
||||
},
|
||||
caseSensitivity:
|
||||
'source values are matched CASE-SENSITIVELY by the engine — write them exactly as listed ' +
|
||||
@@ -270,7 +277,7 @@ export const RULE_AUTHORING_GUIDE = {
|
||||
gatherOutputSeverities: ['Info', 'Warning', 'Error', 'Critical'],
|
||||
gatherCollectorTypes: ['registry', 'eventlog', 'wmi', 'file', 'json', 'xml', 'command_allowlisted', 'logparser'],
|
||||
gatherTriggers: ['startup', 'phase_change', 'phase_exit', 'interval', 'on_event'],
|
||||
analyzeConditionSources: ['event_type', 'event_data', 'event_data_array', 'phase_duration', 'event_count', 'app_install_duration', 'event_correlation'],
|
||||
analyzeConditionSources: ['event_type', 'event_data', 'event_data_array', 'phase_duration', 'event_count', 'app_install_duration', 'event_correlation', 'clock_skew'],
|
||||
analyzeEvaluateOnTriggers: ['enrollment_end', 'whiteglove_sealed', 'on_event:<eventType>'],
|
||||
},
|
||||
|
||||
|
||||
@@ -439,7 +439,16 @@ export const ANALYZE_RULE_SCHEMA: Record<string, unknown> = {
|
||||
"phase_duration",
|
||||
"event_count",
|
||||
"app_install_duration",
|
||||
"event_correlation"
|
||||
"event_correlation",
|
||||
"clock_skew"
|
||||
]
|
||||
},
|
||||
"skewMetric": {
|
||||
"type": "string",
|
||||
"description": "For clock_skew only: which device-clock metric to evaluate. clock_jump = persistent step in the device's clock frame mid-session; sustained_offset = whole session ran on a clock off by at least the threshold. value is the threshold in seconds; operator is limited to gt/gte on the magnitude. IME-log-derived events are excluded from the measurement.",
|
||||
"enum": [
|
||||
"clock_jump",
|
||||
"sustained_offset"
|
||||
]
|
||||
},
|
||||
"eventType": {
|
||||
|
||||
@@ -238,6 +238,7 @@ interface DraftCondition {
|
||||
required?: boolean;
|
||||
correlateEventType?: string;
|
||||
joinField?: string;
|
||||
skewMetric?: string;
|
||||
}
|
||||
|
||||
function checkEventTypeKnown(eventType: string | undefined, where: string): ValidationFinding[] {
|
||||
@@ -293,6 +294,24 @@ function lintAnalyzeRule(rule: Record<string, unknown>): ValidationFinding[] {
|
||||
findings.push(...checkEventTypeKnown(c.correlateEventType, `${label}.correlateEventType`));
|
||||
}
|
||||
|
||||
if (c.source === 'clock_skew') {
|
||||
if (c.skewMetric !== 'clock_jump' && c.skewMetric !== 'sustained_offset') {
|
||||
findings.push({ level: 'error', message: `${label}: clock_skew requires skewMetric ("clock_jump" or "sustained_offset").` });
|
||||
}
|
||||
if (c.operator !== 'gt' && c.operator !== 'gte') {
|
||||
findings.push({ level: 'error', message: `${label}: clock_skew supports only gt/gte — the threshold is compared against the skew MAGNITUDE.` });
|
||||
}
|
||||
const threshold = Number(c.value);
|
||||
if (!c.value || !Number.isFinite(threshold) || threshold <= 0) {
|
||||
findings.push({ level: 'error', message: `${label}: clock_skew requires a positive numeric value (threshold in seconds).` });
|
||||
} else if (threshold < 60) {
|
||||
findings.push({ level: 'warning', message: `${label}: clock_skew threshold below 60 s sits inside normal upload-latency noise — expect false positives.` });
|
||||
}
|
||||
if (c.eventType || c.dataField) {
|
||||
findings.push({ level: 'warning', message: `${label}: clock_skew ignores eventType/dataField — it measures Timestamp against ReceivedAt across the whole session.` });
|
||||
}
|
||||
}
|
||||
|
||||
findings.push(...checkEventTypeKnown(c.eventType, label));
|
||||
|
||||
if ((c.operator === 'regex' || c.operator === 'not_regex') && c.value) {
|
||||
@@ -364,6 +383,9 @@ function lintAnalyzeRule(rule: Record<string, unknown>): ValidationFinding[] {
|
||||
// event_data_array evidence carries the matched element under field=itemField,
|
||||
// so {{itemField}} interpolates at runtime (see EvaluateEventDataArrayCondition).
|
||||
if (c.itemField) resolvable.add(c.itemField);
|
||||
// clock_skew evidence carries a preformatted summary under field=skewSummary,
|
||||
// so {{skewSummary}} interpolates at runtime (see EvaluateClockSkewCondition).
|
||||
if (c.source === 'clock_skew') resolvable.add('skewSummary');
|
||||
}
|
||||
for (const token of extractTokens(rule)) {
|
||||
if (!resolvable.has(token)) {
|
||||
|
||||
@@ -411,7 +411,7 @@ export function registerSessionTools(server: McpServer, ga: boolean, delegated:
|
||||
severity: z.enum(['Info', 'Warning', 'Error', 'Critical']).optional(),
|
||||
source: z.string().optional().describe('Filter by event source/app name (e.g. "MicrosoftTeams")'),
|
||||
fields: z.string().optional()
|
||||
.describe('Comma-separated lean projection (e.g. "eventType,severity,timestamp,message"). Drops the heavy "data" payload unless "data" is listed. Valid keys: eventId, sessionId, tenantId, eventType, severity, source, phase, phaseName, timestamp, receivedAt, message, sequence, rowKey, originalTimestamp, timestampClamped, causedByTransitionStepIndex, causedBySignalOrdinal, data.'),
|
||||
.describe('Comma-separated lean projection (e.g. "eventType,severity,timestamp,message"). Drops the heavy "data" payload unless "data" is listed. Valid keys: eventId, sessionId, tenantId, eventType, severity, source, phase, phaseName, timestamp, receivedAt, sentAt, message, sequence, rowKey, originalTimestamp, timestampClamped, causedByTransitionStepIndex, causedBySignalOrdinal, data.'),
|
||||
pageSize: z.coerce.number().int().min(1).max(1000).optional().default(200)
|
||||
.describe('Page size (1-1000, default 200). The endpoint returns this many events per call; follow nextLink to fetch more.'),
|
||||
continuation: z.string().optional()
|
||||
|
||||
@@ -109,8 +109,17 @@ namespace AutopilotMonitor.Shared.DataAccess
|
||||
/// Reconciles the stored EventCount and RebootCount with the authoritative row counts
|
||||
/// from the Events table (rows dedupe on deterministic RowKeys; the read-modify-write
|
||||
/// increments do not). Call as the last counter write on terminal ingest batches.
|
||||
/// Returns the per-source timestamp-delta samples collected during the same partition
|
||||
/// scan (input to the CMTrace time-skew tripwire), or null when the scan failed.
|
||||
/// </summary>
|
||||
Task ReconcileSessionCountersAsync(string tenantId, string sessionId);
|
||||
Task<SessionSkewScan?> ReconcileSessionCountersAsync(string tenantId, string sessionId);
|
||||
|
||||
/// <summary>
|
||||
/// Bounded histogram of the sourceOffsetOrigin provenance values over a session's
|
||||
/// IME-derived events ("bias" / "line-anchored" / "reader-zone-fallback"). Read only
|
||||
/// on the CMTrace skew tripwire's suspicion path; fail-soft (empty map on error).
|
||||
/// </summary>
|
||||
Task<Dictionary<string, int>> GetImeOffsetOriginHistogramAsync(string tenantId, string sessionId, int maxRows = 500);
|
||||
Task UpdateSessionDiagnosticsBlobAsync(
|
||||
string tenantId, string sessionId, string blobName, string? destination = null);
|
||||
Task SetSessionPreProvisionedAsync(string tenantId, string sessionId, bool isPreProvisioned,
|
||||
|
||||
@@ -38,6 +38,16 @@ namespace AutopilotMonitor.Shared.Models
|
||||
/// </summary>
|
||||
public DateTime? ReceivedAt { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// Device-clock UTC timestamp of the moment the agent SENT the upload batch carrying
|
||||
/// this event (X-Send-Time-Utc request header, one value per ingest request — never
|
||||
/// set by the agent per event). Same clock frame as <see cref="Timestamp"/>, so
|
||||
/// SentAt − Timestamp is pure spool delay and ReceivedAt − SentAt is network latency
|
||||
/// plus device-vs-server clock offset — the two are indistinguishable without this
|
||||
/// field. Null for events from agents that pre-date the header.
|
||||
/// </summary>
|
||||
public DateTime? SentAt { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// Type of event (e.g., "phase_transition", "app_install_start", "error")
|
||||
/// </summary>
|
||||
|
||||
@@ -222,11 +222,19 @@ namespace AutopilotMonitor.Shared.Models
|
||||
|
||||
/// <summary>
|
||||
/// Source of the signal: "event_type", "event_data", "event_data_array", "phase_duration",
|
||||
/// "event_count", "app_install_duration", "event_correlation".
|
||||
/// "event_count", "app_install_duration", "event_correlation", "clock_skew".
|
||||
/// Must stay in sync with DryRunAnalyzeRuleFunction.KnownSources and the RuleEngine switch.
|
||||
/// </summary>
|
||||
public string Source { get; set; } = default!;
|
||||
|
||||
/// <summary>
|
||||
/// For "clock_skew" only: which device-clock metric to evaluate — "clock_jump"
|
||||
/// (persistent step in the device's clock frame mid-session) or "sustained_offset"
|
||||
/// (whole session ran on a clock off by ≥ Value). Value is the threshold in seconds;
|
||||
/// Operator is limited to gt/gte on the magnitude.
|
||||
/// </summary>
|
||||
public string? SkewMetric { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// Event type to match on.
|
||||
/// For "event_type"/"event_data": the event type to match.
|
||||
|
||||
@@ -61,6 +61,14 @@ namespace AutopilotMonitor.Shared.Models
|
||||
public List<EnrollmentEvent> Events { get; set; }
|
||||
public bool IsCompressed { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// Device-clock send time of the carrying upload request (X-Send-Time-Utc header),
|
||||
/// parsed by the ingest function. One value per request; stamped onto every event
|
||||
/// in <c>EventIngestProcessor.StampServerFields</c>. Null when the agent pre-dates
|
||||
/// the header or sent an unparseable value.
|
||||
/// </summary>
|
||||
public DateTime? SentAt { get; set; }
|
||||
|
||||
public IngestEventsRequest()
|
||||
{
|
||||
Events = new List<EnrollmentEvent>();
|
||||
|
||||
@@ -0,0 +1,31 @@
|
||||
using System.Collections.Generic;
|
||||
|
||||
namespace AutopilotMonitor.Shared.Models
|
||||
{
|
||||
/// <summary>
|
||||
/// Per-session timestamp-delta samples collected during the terminal counter reconcile's
|
||||
/// single event-partition scan (zero extra storage reads). Samples are split by producing
|
||||
/// source: CMTrace-derived events (Source == "ImeLogTracker") versus everything else.
|
||||
/// Consumed by the CMTrace time-skew tripwire, which compares the two sides' median
|
||||
/// (ReceivedAt − OccurredUtc) deltas — shared upload/spool latency is common-mode and
|
||||
/// cancels in that difference; a timezone mis-conversion shifts only the IME side.
|
||||
/// </summary>
|
||||
public class SessionSkewScan
|
||||
{
|
||||
/// <summary>(ReceivedAt − OccurredUtc) in minutes for events with Source == "ImeLogTracker".</summary>
|
||||
public List<double> ImeDeltaMinutes { get; } = new List<double>();
|
||||
|
||||
/// <summary>(ReceivedAt − OccurredUtc) in minutes for all other event sources.</summary>
|
||||
public List<double> OtherDeltaMinutes { get; } = new List<double>();
|
||||
|
||||
/// <summary>
|
||||
/// Distinct ReceivedAt values seen on the IME side. ReceivedAt is stamped once per
|
||||
/// upload BATCH, not per event — a median over one or two batches is a
|
||||
/// batch-composition artifact, not a session property.
|
||||
/// </summary>
|
||||
public int ImeDistinctBatchCount { get; set; }
|
||||
|
||||
/// <summary>Distinct ReceivedAt values seen on the non-IME side.</summary>
|
||||
public int OtherDistinctBatchCount { get; set; }
|
||||
}
|
||||
}
|
||||
@@ -146,6 +146,17 @@ const OPS_EVENT_TYPES: Record<string, string[]> = {
|
||||
// ReportAgentErrorFunction (RecordAgentEmergencyBreakAsync). Dual-register per memory
|
||||
// feedback_ops_event_types_dual_register.
|
||||
"AgentEmergencyBreak",
|
||||
// The running exe's SHA-256 differs from the backend-advertised hash for its version —
|
||||
// the field binary is not the published build (tamper / stale blob / uncommitted-tree
|
||||
// build). Emitted by ReportAgentErrorFunction (RecordAgentBinaryIntegrityMismatchAsync).
|
||||
// Dual-register per memory feedback_ops_event_types_dual_register.
|
||||
"AgentBinaryIntegrityMismatch",
|
||||
// CMTrace time-skew regression tripwire: a terminal session's IME-derived event
|
||||
// timestamps diverged from its other events by a clean 15-minute-grid multiple — the
|
||||
// per-line self-anchoring missed a case. Goal state: never fires. Emitted by
|
||||
// EventIngestProcessor (RecordCmTraceTimeSkewRegressionAsync). Dual-register per memory
|
||||
// feedback_ops_event_types_dual_register.
|
||||
"CmTraceTimeSkewRegression",
|
||||
],
|
||||
Platform: [
|
||||
// Azure Monitor alerts relayed through POST ops/alert-webhook (Common Alert Schema →
|
||||
|
||||
@@ -315,10 +315,10 @@ export function SectionTenantGroups() {
|
||||
return (
|
||||
<div key={t.groupId} className="border border-gray-200 rounded-lg">
|
||||
{/* Group header */}
|
||||
<div className="px-4 py-2 border-b border-gray-100 bg-gray-50 rounded-t-lg flex items-center justify-between gap-2">
|
||||
<div className="px-4 py-2 border-b border-gray-100 bg-gray-50 rounded-t-lg flex flex-col gap-2 sm:flex-row sm:items-center sm:justify-between">
|
||||
<div className="min-w-0">
|
||||
<span className="font-medium text-gray-900 truncate">{t.name}</span>
|
||||
<span className="ml-2 text-xs text-gray-500">
|
||||
<span className="font-medium text-gray-900 break-words">{t.name}</span>
|
||||
<span className="ml-2 text-xs text-gray-500 whitespace-nowrap">
|
||||
{t.tenantIds.length} tenant{t.tenantIds.length === 1 ? "" : "s"} · {t.assigneeCount} assignee
|
||||
{t.assigneeCount === 1 ? "" : "s"}
|
||||
</span>
|
||||
@@ -341,7 +341,7 @@ export function SectionTenantGroups() {
|
||||
|
||||
<div className="p-4 grid gap-4 md:grid-cols-2">
|
||||
{/* Tenants column */}
|
||||
<div className="space-y-2">
|
||||
<div className="min-w-0 space-y-2">
|
||||
<p className="text-xs font-semibold text-gray-700 uppercase tracking-wide">Tenants</p>
|
||||
{t.tenantIds.length === 0 ? (
|
||||
<p className="text-sm text-gray-400">No tenants yet.</p>
|
||||
@@ -349,11 +349,11 @@ export function SectionTenantGroups() {
|
||||
<ul className="space-y-1">
|
||||
{t.tenantIds.map((id) => (
|
||||
<li key={id} className="flex items-center justify-between gap-2 text-sm">
|
||||
<span className="truncate text-gray-900">{domainOf(id) || id}</span>
|
||||
<span className="min-w-0 truncate text-gray-900">{domainOf(id) || id}</span>
|
||||
<button
|
||||
onClick={() => handleRemoveTenant(t, id)}
|
||||
disabled={busyKey === `rmtenant:${t.groupId}:${id}`}
|
||||
className="text-red-600 hover:text-red-800 disabled:opacity-50 text-xs"
|
||||
className="shrink-0 text-red-600 hover:text-red-800 disabled:opacity-50 text-xs"
|
||||
aria-label={`Remove ${domainOf(id) || id}`}
|
||||
>
|
||||
Remove
|
||||
@@ -378,7 +378,7 @@ export function SectionTenantGroups() {
|
||||
<button
|
||||
onClick={() => handleAddTenant(t)}
|
||||
disabled={!tenantToAdd[t.groupId] || busyKey === `addtenant:${t.groupId}`}
|
||||
className="px-3 py-1.5 text-sm bg-sky-600 text-white rounded-lg hover:bg-sky-700 disabled:opacity-50 transition-colors"
|
||||
className="shrink-0 px-3 py-1.5 text-sm bg-sky-600 text-white rounded-lg hover:bg-sky-700 disabled:opacity-50 transition-colors"
|
||||
>
|
||||
Add
|
||||
</button>
|
||||
@@ -386,24 +386,27 @@ export function SectionTenantGroups() {
|
||||
</div>
|
||||
|
||||
{/* Assignees column */}
|
||||
<div className="space-y-2">
|
||||
<div className="min-w-0 space-y-2">
|
||||
<p className="text-xs font-semibold text-gray-700 uppercase tracking-wide">Assignees</p>
|
||||
{t.assignees.length === 0 ? (
|
||||
<p className="text-sm text-gray-400">No one assigned yet.</p>
|
||||
) : (
|
||||
<ul className="space-y-1">
|
||||
<ul className="space-y-2">
|
||||
{t.assignees.map((a) => (
|
||||
<li key={a.upn} className="flex items-center justify-between gap-2 text-sm">
|
||||
<span className="min-w-0 truncate text-gray-900">
|
||||
{a.upn}
|
||||
<span className="ml-1.5 inline-flex items-center px-1.5 py-0.5 rounded text-xs font-medium bg-sky-100 text-sky-800">
|
||||
{ROLE_LABELS[a.role] ?? a.role}
|
||||
</span>
|
||||
<li
|
||||
key={a.upn}
|
||||
className="flex flex-wrap items-center gap-x-1.5 gap-y-1 text-sm"
|
||||
>
|
||||
{/* Full-width UPN on phones so it is not hyphen-broken; the badge and
|
||||
Remove then share the wrapped line below it. */}
|
||||
<span className="w-full break-all text-gray-900 sm:w-auto sm:min-w-0">{a.upn}</span>
|
||||
<span className="inline-flex items-center px-1.5 py-0.5 rounded text-xs font-medium bg-sky-100 text-sky-800">
|
||||
{ROLE_LABELS[a.role] ?? a.role}
|
||||
</span>
|
||||
<button
|
||||
onClick={() => handleUnassign(t, a.upn)}
|
||||
disabled={busyKey === `unassign:${t.groupId}:${a.upn}`}
|
||||
className="text-red-600 hover:text-red-800 disabled:opacity-50 text-xs shrink-0"
|
||||
className="ml-auto shrink-0 text-red-600 hover:text-red-800 disabled:opacity-50 text-xs"
|
||||
aria-label={`Remove ${a.upn}`}
|
||||
>
|
||||
Remove
|
||||
@@ -412,7 +415,7 @@ export function SectionTenantGroups() {
|
||||
))}
|
||||
</ul>
|
||||
)}
|
||||
<div className="flex gap-2 pt-1">
|
||||
<div className="flex flex-wrap gap-2 pt-1">
|
||||
<input
|
||||
type="email"
|
||||
value={assignUpn[t.groupId] || ""}
|
||||
@@ -425,12 +428,12 @@ export function SectionTenantGroups() {
|
||||
}}
|
||||
placeholder="user@domain.com"
|
||||
autoComplete="off"
|
||||
className="flex-1 min-w-0 px-3 py-1.5 border border-gray-300 rounded-lg text-sm text-gray-900 placeholder-gray-500 focus:outline-none focus:ring-2 focus:ring-sky-500 transition-colors"
|
||||
className="w-full sm:w-auto sm:flex-1 min-w-0 px-3 py-1.5 border border-gray-300 rounded-lg text-sm text-gray-900 placeholder-gray-500 focus:outline-none focus:ring-2 focus:ring-sky-500 transition-colors"
|
||||
/>
|
||||
<select
|
||||
value={assignRole[t.groupId] || "DelegatedReader"}
|
||||
onChange={(e) => setAssignRole((p) => ({ ...p, [t.groupId]: e.target.value }))}
|
||||
className="px-2 py-1.5 border border-gray-300 rounded-lg text-sm text-gray-900 bg-white focus:outline-none focus:ring-2 focus:ring-sky-500 transition-colors"
|
||||
className="flex-1 sm:flex-none min-w-0 px-2 py-1.5 border border-gray-300 rounded-lg text-sm text-gray-900 bg-white focus:outline-none focus:ring-2 focus:ring-sky-500 transition-colors"
|
||||
>
|
||||
<option value="DelegatedReader">Reader</option>
|
||||
<option value="DelegatedAdmin">Admin</option>
|
||||
@@ -438,7 +441,7 @@ export function SectionTenantGroups() {
|
||||
<button
|
||||
onClick={() => handleAssign(t)}
|
||||
disabled={!(assignUpn[t.groupId] || "").trim() || busyKey === `assign:${t.groupId}`}
|
||||
className="px-3 py-1.5 text-sm bg-sky-600 text-white rounded-lg hover:bg-sky-700 disabled:opacity-50 transition-colors"
|
||||
className="shrink-0 px-3 py-1.5 text-sm bg-sky-600 text-white rounded-lg hover:bg-sky-700 disabled:opacity-50 transition-colors"
|
||||
>
|
||||
Assign
|
||||
</button>
|
||||
|
||||
@@ -382,6 +382,7 @@ export default function AnalyzeRuleCard({
|
||||
<span className="text-gray-600 font-medium">Source:</span> {condition.source}
|
||||
{condition.eventType && (<span> | <span className="text-gray-600 font-medium">Event Type:</span> {condition.eventType}</span>)}
|
||||
{condition.dataField && (<span> | <span className="text-gray-600 font-medium">Field:</span> <code className="bg-gray-200 px-1 rounded text-xs">{condition.dataField}</code></span>)}
|
||||
{condition.skewMetric && (<span> | <span className="text-gray-600 font-medium">Skew Metric:</span> <code className="bg-gray-200 px-1 rounded text-xs">{condition.skewMetric}</code></span>)}
|
||||
</p>
|
||||
<p>
|
||||
<span className="text-gray-600 font-medium">Operator:</span> <code className="bg-gray-200 px-1 rounded text-xs">{condition.operator}</code>{" "}
|
||||
|
||||
+20
-2
@@ -2,7 +2,7 @@
|
||||
|
||||
import {
|
||||
RuleForm, RuleCondition, RulePrecondition,
|
||||
CATEGORIES, SEVERITIES, TRIGGERS, OPERATORS, SOURCES, PRECONDITION_OPERATORS,
|
||||
CATEGORIES, SEVERITIES, TRIGGERS, OPERATORS, SOURCES, PRECONDITION_OPERATORS, SKEW_METRICS,
|
||||
EMPTY_CONDITION, EMPTY_FACTOR, EMPTY_PRECONDITION,
|
||||
validateOnEventTypes,
|
||||
} from "../types";
|
||||
@@ -184,6 +184,7 @@ export default function AnalyzeRuleFormFields({ form, setForm, showRuleId, exist
|
||||
{form.conditions.map((cond, idx) => {
|
||||
const isCorrelation = cond.source === "event_correlation";
|
||||
const isArray = cond.source === "event_data_array";
|
||||
const isClockSkew = cond.source === "clock_skew";
|
||||
const updateCond = (patch: Partial<RuleCondition>) => {
|
||||
const c = [...form.conditions];
|
||||
c[idx] = { ...c[idx], ...patch };
|
||||
@@ -196,6 +197,7 @@ export default function AnalyzeRuleFormFields({ form, setForm, showRuleId, exist
|
||||
Condition {idx + 1}
|
||||
{isCorrelation && <span className="ml-2 px-1.5 py-0.5 bg-indigo-100 text-indigo-700 rounded text-xs">event_correlation</span>}
|
||||
{isArray && <span className="ml-2 px-1.5 py-0.5 bg-teal-100 text-teal-700 rounded text-xs">event_data_array</span>}
|
||||
{isClockSkew && <span className="ml-2 px-1.5 py-0.5 bg-amber-100 text-amber-700 rounded text-xs">clock_skew</span>}
|
||||
</span>
|
||||
{form.conditions.length > 1 && (
|
||||
<button type="button" onClick={() => setForm({ ...form, conditions: form.conditions.filter((_, i) => i !== idx) })} className="text-xs text-red-500 hover:text-red-700">Remove</button>
|
||||
@@ -205,7 +207,7 @@ export default function AnalyzeRuleFormFields({ form, setForm, showRuleId, exist
|
||||
{/* Row 1: Signal, Source, Event Type A */}
|
||||
<div className="grid grid-cols-1 sm:grid-cols-3 gap-2">
|
||||
<input type="text" value={cond.signal} onChange={(e) => updateCond({ signal: e.target.value })} placeholder="Signal name" autoComplete="off" className="px-3 py-1.5 border border-gray-300 rounded text-sm text-gray-900 placeholder-gray-400 focus:outline-none focus:ring-1 focus:ring-green-500" />
|
||||
<select value={cond.source} onChange={(e) => updateCond({ source: e.target.value })} className="px-3 py-1.5 border border-gray-300 rounded text-sm text-gray-900 bg-white focus:outline-none focus:ring-1 focus:ring-green-500">
|
||||
<select value={cond.source} onChange={(e) => updateCond({ source: e.target.value, ...(e.target.value === "clock_skew" && !cond.skewMetric ? { skewMetric: "clock_jump" } : {}) })} className="px-3 py-1.5 border border-gray-300 rounded text-sm text-gray-900 bg-white focus:outline-none focus:ring-1 focus:ring-green-500">
|
||||
{SOURCES.map((s) => (<option key={s} value={s}>{s}</option>))}
|
||||
</select>
|
||||
<input type="text" value={cond.eventType} onChange={(e) => updateCond({ eventType: e.target.value })} placeholder={isCorrelation ? "Event A type (e.g. app_install_completed)" : "Event type"} autoComplete="off" className="px-3 py-1.5 border border-gray-300 rounded text-sm text-gray-900 placeholder-gray-400 focus:outline-none focus:ring-1 focus:ring-green-500" />
|
||||
@@ -259,6 +261,22 @@ export default function AnalyzeRuleFormFields({ form, setForm, showRuleId, exist
|
||||
</div>
|
||||
)}
|
||||
|
||||
{/* clock_skew extra fields */}
|
||||
{isClockSkew && (
|
||||
<div className="pt-2 border-t border-amber-200 space-y-2">
|
||||
<p className="text-xs font-medium text-amber-700">Clock skew settings</p>
|
||||
<div>
|
||||
<label className="block text-xs text-gray-500 mb-1">Skew metric <span className="text-red-500">*</span></label>
|
||||
<select value={cond.skewMetric ?? "clock_jump"} onChange={(e) => updateCond({ skewMetric: e.target.value })} className="w-full px-3 py-1.5 border border-amber-300 rounded text-sm text-gray-900 bg-white focus:outline-none focus:ring-1 focus:ring-amber-500">
|
||||
{SKEW_METRICS.map((m) => (<option key={m} value={m}>{m}</option>))}
|
||||
</select>
|
||||
</div>
|
||||
<p className="text-xs text-gray-500">
|
||||
<strong>Value</strong> is the threshold in seconds; operator is limited to <code className="bg-gray-100 px-1 rounded">gt</code>/<code className="bg-gray-100 px-1 rounded">gte</code> on the skew magnitude. Event type and data field are ignored — the metric measures each event's timestamp against the server receive time across the whole session (IME-log-derived events excluded). <code className="bg-gray-100 px-1 rounded">clock_jump</code> = persistent mid-session step; <code className="bg-gray-100 px-1 rounded">sustained_offset</code> = whole session off by at least the threshold.
|
||||
</p>
|
||||
</div>
|
||||
)}
|
||||
|
||||
{/* event_data_array extra field */}
|
||||
{isArray && (
|
||||
<div className="pt-2 border-t border-teal-200 space-y-2">
|
||||
|
||||
@@ -37,6 +37,9 @@ export interface RuleCondition {
|
||||
eventAFilterField?: string;
|
||||
eventAFilterOperator?: string;
|
||||
eventAFilterValue?: string;
|
||||
// clock_skew: which device-clock metric to evaluate ("clock_jump" | "sustained_offset");
|
||||
// value is the threshold in seconds, operator is limited to gt/gte on the magnitude
|
||||
skewMetric?: string;
|
||||
}
|
||||
|
||||
export interface RulePrecondition {
|
||||
@@ -126,7 +129,8 @@ export const CATEGORIES = ["network", "identity", "apps", "device", "esp", "enro
|
||||
export const SEVERITIES = ["info", "warning", "high", "critical"] as const;
|
||||
export const TRIGGERS = ["single", "correlation"] as const;
|
||||
export const OPERATORS = ["equals", "not_equals", "contains", "not_contains", "regex", "not_regex", "gt", "lt", "gte", "lte", "exists", "not_exists", "count_gte", "count_per_group_gte", "in", "not_in"] as const;
|
||||
export const SOURCES = ["event_type", "event_data", "event_data_array", "phase_duration", "app_install_duration", "event_count", "event_correlation"] as const;
|
||||
export const SOURCES = ["event_type", "event_data", "event_data_array", "phase_duration", "app_install_duration", "event_count", "event_correlation", "clock_skew"] as const;
|
||||
export const SKEW_METRICS = ["clock_jump", "sustained_offset"] as const;
|
||||
export const PRECONDITION_OPERATORS = ["equals", "not_equals", "contains", "not_contains", "regex", "not_regex", "gt", "lt", "gte", "lte", "exists", "not_exists", "in", "not_in"] as const;
|
||||
|
||||
export const SEVERITY_COLORS: Record<string, { bg: string; text: string; border: string; dot: string }> = {
|
||||
@@ -168,6 +172,9 @@ export const EMPTY_CONDITION: RuleCondition = {
|
||||
eventAFilterField: "",
|
||||
eventAFilterOperator: "equals",
|
||||
eventAFilterValue: "",
|
||||
// skewMetric deliberately absent: it is an enum field ("clock_jump" | "sustained_offset")
|
||||
// and an empty string would violate the schema — the source select defaults it when
|
||||
// switching a condition to clock_skew.
|
||||
};
|
||||
|
||||
export const EMPTY_FACTOR: ConfidenceFactor = {
|
||||
|
||||
@@ -4,6 +4,8 @@ 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 { formatDuration, formatUtcOffset } from "@/lib/formatting";
|
||||
|
||||
interface EventTimelineProps {
|
||||
filteredEvents: EnrollmentEvent[];
|
||||
@@ -184,7 +186,7 @@ export default function EventTimeline({
|
||||
<RawEventRow
|
||||
key={ev.eventId || `${ev.sessionId}-${ev.sequence}`}
|
||||
event={ev}
|
||||
prevDisplayTime={i > 0 ? getDisplayTime(sortedBySequence[i - 1]) : null}
|
||||
prevEvent={i > 0 ? sortedBySequence[i - 1] : null}
|
||||
/>
|
||||
))}
|
||||
</div>
|
||||
@@ -350,7 +352,7 @@ function PhaseSection({
|
||||
key={event.eventId || `${event.sessionId}-${event.sequence}`}
|
||||
event={event}
|
||||
showScriptOutput={showScriptOutput}
|
||||
prevDisplayTime={i > 0 ? getDisplayTime(events[i - 1]) : null}
|
||||
prevEvent={i > 0 ? events[i - 1] : null}
|
||||
/>
|
||||
))}
|
||||
</div>
|
||||
@@ -402,11 +404,61 @@ function GapBadge({ prevTime, eventTime }: { prevTime: Date | null; eventTime: D
|
||||
);
|
||||
}
|
||||
|
||||
function EventRow({ event, showScriptOutput, prevDisplayTime }: { event: EnrollmentEvent; showScriptOutput?: boolean; prevDisplayTime?: Date | null }) {
|
||||
// A displayed time stepping BACKWARDS within the sequence order is information, not a
|
||||
// rendering bug (P13): rows are ordered by the clock-immune sequence counter, while the
|
||||
// displayed time is corrected UTC — a backdated log line or an era-mixed log makes it
|
||||
// step back. Shown on the row AFTER the jump (GapBadge convention) and only at ≥5 min
|
||||
// (BACKWARD_JUMP_THRESHOLD_MS), so normal interleaved-writer jitter (≤2 min by the
|
||||
// agent's grid tolerance) never renders a badge. Known causes get the informational sky
|
||||
// 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 }) {
|
||||
if (!prevEvent) return null;
|
||||
const jump = classifyTimeJump(
|
||||
{ displayTime: getDisplayTime(prevEvent), provenance: readTimeProvenance(prevEvent.data) },
|
||||
{ displayTime: getDisplayTime(event), provenance: readTimeProvenance(event.data) },
|
||||
);
|
||||
if (!jump) return null;
|
||||
|
||||
const label = jump.deltaMs >= 48 * 60 * 60 * 1000
|
||||
? `−${Math.round(jump.deltaMs / (24 * 60 * 60 * 1000))}d`
|
||||
: jump.deltaMs >= 60 * 60 * 1000
|
||||
? `−${Math.round(jump.deltaMs / (60 * 60 * 1000))}h`
|
||||
: `−${Math.round(jump.deltaMs / (60 * 1000))}m`;
|
||||
const human = formatDuration(jump.deltaMs / 1000);
|
||||
const times = `(${getDisplayTime(prevEvent).toLocaleTimeString()} → ${getDisplayTime(event).toLocaleTimeString()})`;
|
||||
|
||||
const title =
|
||||
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}`
|
||||
: jump.cause === "rejected-source"
|
||||
? `Time moved backwards by ${human} vs the previous event ${times}. The line's own timestamp was rejected by the staleness clamp; the agent's clock time is shown instead. ${TIME_JUMP_ORDER_NOTE}`
|
||||
: `Time moved backwards by ${human} vs the previous event ${times}. ${TIME_JUMP_ORDER_NOTE} Displayed times are corrected UTC and can step backwards when the source log mixes clock eras.`;
|
||||
|
||||
const color = jump.cause ? "bg-sky-100 text-sky-800" : "bg-amber-100 text-amber-800";
|
||||
return (
|
||||
<span className={`px-1.5 py-0.5 rounded text-xs font-medium whitespace-nowrap flex-shrink-0 ${color}`} title={title}>
|
||||
↩ {label}
|
||||
</span>
|
||||
);
|
||||
}
|
||||
|
||||
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 }) {
|
||||
const prevDisplayTime = prevEvent ? getDisplayTime(prevEvent) : null;
|
||||
const [showDetails, setShowDetails] = useState(false);
|
||||
const [showRaw, setShowRaw] = useState(false);
|
||||
const [copied, setCopied] = useState(false);
|
||||
const [copiedDetail, setCopiedDetail] = useState(false);
|
||||
// Collapsed by default: the same values sit in the raw JSON dump — this labeled view is
|
||||
// an opt-in dive, it must not inflate the metadata block (user decision 2026-08-20).
|
||||
const [showProvenance, setShowProvenance] = useState(false);
|
||||
const timeProvenance = useMemo(() => readTimeProvenance(event.data), [event.data]);
|
||||
const rawDetailData = useMemo(() => normalizeEventDataForDisplay(event.data), [event.data]);
|
||||
|
||||
// Filter stdout from script events when showScriptOutput is false.
|
||||
@@ -489,6 +541,7 @@ function EventRow({ event, showScriptOutput, prevDisplayTime }: { event: Enrollm
|
||||
)}
|
||||
</span>
|
||||
<GapBadge prevTime={prevDisplayTime ?? null} eventTime={recordedAt ?? new Date(event.timestamp)} />
|
||||
<TimeJumpBadge prevEvent={prevEvent} event={event} />
|
||||
<SeverityBadge severity={event.severity} />
|
||||
{isBackfilled && (
|
||||
<span
|
||||
@@ -498,6 +551,14 @@ function EventRow({ event, showScriptOutput, prevDisplayTime }: { event: Enrollm
|
||||
⟲ Backfilled
|
||||
</span>
|
||||
)}
|
||||
{event.timestampClamped && (
|
||||
<span
|
||||
className="px-2 py-0.5 rounded text-xs font-medium bg-amber-100 text-amber-800"
|
||||
title={`${CLAMPED_TOOLTIP_PREFIX}${event.originalTimestamp ? ` Original device timestamp: ${event.originalTimestamp}.` : ""}`}
|
||||
>
|
||||
⧖ Clamped
|
||||
</span>
|
||||
)}
|
||||
<span className="text-sm font-medium text-gray-900">{event.eventType}</span>
|
||||
</div>
|
||||
<p className="mt-1 text-sm text-gray-600" title={event.message || undefined}>{shortenBuildHashInMessage(event.message)}</p>
|
||||
@@ -680,8 +741,23 @@ function EventRow({ event, showScriptOutput, prevDisplayTime }: { event: Enrollm
|
||||
)}
|
||||
<div className="flex mt-0.5">
|
||||
<span className="w-16 flex-shrink-0 text-gray-400">Created</span>
|
||||
<span className="font-mono">{event.timestamp}</span>
|
||||
<span className="font-mono">
|
||||
{event.timestamp}
|
||||
{(timeProvenance || event.timestampClamped) && (
|
||||
<button
|
||||
type="button"
|
||||
onClick={() => setShowProvenance(!showProvenance)}
|
||||
className="ml-2 font-sans text-gray-400 hover:text-green-600"
|
||||
title="How this timestamp was produced (offset, origin, raw log time)"
|
||||
>
|
||||
{showProvenance ? "▾ time provenance" : "▸ time provenance"}
|
||||
</button>
|
||||
)}
|
||||
</span>
|
||||
</div>
|
||||
{showProvenance && (timeProvenance || event.timestampClamped) && (
|
||||
<TimeProvenanceRows event={event} provenance={timeProvenance} />
|
||||
)}
|
||||
<div className="flex mt-0.5">
|
||||
<span className="w-16 flex-shrink-0 text-gray-400">Received</span>
|
||||
<span className="font-mono">
|
||||
@@ -817,11 +893,108 @@ function EventRow({ event, showScriptOutput, prevDisplayTime }: { event: Enrollm
|
||||
);
|
||||
}
|
||||
|
||||
function RawEventRow({ event, prevDisplayTime }: { event: EnrollmentEvent; prevDisplayTime?: Date | null }) {
|
||||
// Origin chip styling/wording for the sourceOffsetOrigin provenance value. Unknown
|
||||
// values render verbatim in gray so a future agent origin never breaks the UI.
|
||||
const ORIGIN_CHIP: Record<string, { className: string; title: string }> = {
|
||||
"line-anchored": {
|
||||
className: "bg-sky-100 text-sky-800",
|
||||
title: "Offset anchored to a UTC reference line near this log line — the most precise source.",
|
||||
},
|
||||
bias: {
|
||||
className: "bg-slate-200 text-slate-600",
|
||||
title: "Offset taken from the log line's own timezone bias — declared by the writer, authoritative.",
|
||||
},
|
||||
"reader-zone-fallback": {
|
||||
className: "bg-amber-100 text-amber-800",
|
||||
title: "No anchor available — the reader's timezone was assumed for the whole file. Times are internally consistent but the absolute frame may be wrong.",
|
||||
},
|
||||
calibrated: {
|
||||
className: "bg-gray-100 text-gray-500",
|
||||
title: "Legacy origin emitted by older agents (retired).",
|
||||
},
|
||||
};
|
||||
|
||||
// The raw CMTrace time-resolution values (P13): how this event's UTC timestamp was
|
||||
// produced. Collapsed behind the "time provenance" toggle on the Created row — the same
|
||||
// values sit in the raw JSON dump, so this labeled view is an opt-in dive that must not
|
||||
// inflate the default metadata block. Per-row badges stay reserved for jump/clamp cases.
|
||||
function TimeProvenanceRows({ event, provenance }: { event: EnrollmentEvent; provenance: ReturnType<typeof readTimeProvenance> }) {
|
||||
const origin = provenance?.sourceOffsetOrigin;
|
||||
const originChip = origin ? ORIGIN_CHIP[origin] ?? { className: "bg-gray-100 text-gray-500", title: origin } : null;
|
||||
|
||||
return (
|
||||
<div className="ml-2 pl-2 border-l-2 border-gray-200">
|
||||
{provenance?.sourceLocalTs && (
|
||||
<div className="flex mt-0.5">
|
||||
<span className="w-24 flex-shrink-0 text-gray-400">Local time</span>
|
||||
<span className="font-mono">
|
||||
{provenance.sourceLocalTs}
|
||||
<span className="text-gray-400 ml-1 font-sans">(as written in the log)</span>
|
||||
</span>
|
||||
</div>
|
||||
)}
|
||||
{provenance?.sourceOffsetMinutes !== null && provenance?.sourceOffsetMinutes !== undefined && (
|
||||
<div className="flex mt-0.5 items-center">
|
||||
<span className="w-24 flex-shrink-0 text-gray-400">UTC offset</span>
|
||||
<span className="font-mono">{formatUtcOffset(provenance.sourceOffsetMinutes)}</span>
|
||||
<span className="text-gray-400 ml-1">(applied)</span>
|
||||
{originChip && origin && (
|
||||
<span className={`ml-2 px-1.5 py-0.5 rounded text-[10px] font-medium ${originChip.className}`} title={originChip.title}>
|
||||
{origin}
|
||||
{origin === "calibrated" && <span className="ml-1 font-normal">(retired)</span>}
|
||||
</span>
|
||||
)}
|
||||
</div>
|
||||
)}
|
||||
{provenance?.measuredWriterOffsetMinutes !== null && provenance?.measuredWriterOffsetMinutes !== undefined && (
|
||||
<div className="flex mt-0.5">
|
||||
<span className="w-24 flex-shrink-0 text-gray-400">Writer offset</span>
|
||||
<span
|
||||
className="font-mono"
|
||||
title="Measured from the log writer's paired local/UTC lines. Sticky after era flip-backs, so it can lag reality. The applied correction is the UTC offset above."
|
||||
>
|
||||
{formatUtcOffset(provenance.measuredWriterOffsetMinutes)}
|
||||
<span className="text-gray-400 ml-1 font-sans">(observed from the writer's own UTC lines — not the applied correction)</span>
|
||||
</span>
|
||||
</div>
|
||||
)}
|
||||
{provenance?.derivedTimestamp && (
|
||||
<div className="flex mt-0.5">
|
||||
<span className="w-24 flex-shrink-0 text-gray-400">Derived time</span>
|
||||
<span className="font-mono">
|
||||
{provenance.derivedTimestamp}
|
||||
<span className="text-gray-400 ml-1 font-sans">(line timestamp unusable — agent clock substituted)</span>
|
||||
</span>
|
||||
</div>
|
||||
)}
|
||||
{provenance?.rejectedSourceTimestamp && (
|
||||
<div className="flex mt-0.5">
|
||||
<span className="w-24 flex-shrink-0 text-gray-400">Rejected time</span>
|
||||
<span className="font-mono">
|
||||
{provenance.rejectedSourceTimestamp}
|
||||
<span className="text-gray-400 ml-1 font-sans">(rejected by the staleness clamp)</span>
|
||||
</span>
|
||||
</div>
|
||||
)}
|
||||
{event.timestampClamped && (
|
||||
<div className="flex mt-0.5">
|
||||
<span className="w-24 flex-shrink-0 text-gray-400">Original time</span>
|
||||
<span className="font-mono">
|
||||
{event.originalTimestamp ?? "—"}
|
||||
<span className="text-gray-400 ml-1 font-sans">(before ingest clamp)</span>
|
||||
</span>
|
||||
</div>
|
||||
)}
|
||||
</div>
|
||||
);
|
||||
}
|
||||
|
||||
function RawEventRow({ event, prevEvent }: { event: EnrollmentEvent; prevEvent?: EnrollmentEvent | null }) {
|
||||
const [expanded, setExpanded] = useState(false);
|
||||
const detailData = useMemo(() => normalizeEventDataForDisplay(event.data), [event.data]);
|
||||
const hasDetails = detailData && Object.keys(detailData).length > 0;
|
||||
const { isBackfilled, recordedAt } = getBackfillInfo(event);
|
||||
const prevDisplayTime = prevEvent ? getDisplayTime(prevEvent) : null;
|
||||
|
||||
const sevColor: Record<string, string> = {
|
||||
Trace: "text-purple-500",
|
||||
@@ -838,10 +1011,14 @@ function RawEventRow({ event, prevDisplayTime }: { event: EnrollmentEvent; prevD
|
||||
<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} />
|
||||
<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>
|
||||
)}
|
||||
{event.timestampClamped && (
|
||||
<span className="text-amber-600 flex-shrink-0" title={`${CLAMPED_TOOLTIP_PREFIX}${event.originalTimestamp ? ` Original device timestamp: ${event.originalTimestamp}.` : ""}`}>⧖</span>
|
||||
)}
|
||||
<span className="text-gray-900 font-medium flex-shrink-0">{event.eventType}</span>
|
||||
<span className="text-gray-500 truncate flex-1 min-w-0" title={event.message || undefined}>{shortenBuildHashInMessage(event.message)}</span>
|
||||
{hasDetails && (
|
||||
|
||||
@@ -1,5 +1,5 @@
|
||||
import { describe, it, expect } from "vitest";
|
||||
import { formatBytes, formatThroughput, formatDuration, formatPercent } from "../formatting";
|
||||
import { formatBytes, formatThroughput, formatDuration, formatPercent, formatUtcOffset } from "../formatting";
|
||||
|
||||
describe("formatBytes", () => {
|
||||
it("returns the zero sentinel for 0 / negative / non-finite", () => {
|
||||
@@ -51,3 +51,17 @@ describe("formatPercent", () => {
|
||||
expect(formatPercent(5, 0)).toBe("—");
|
||||
});
|
||||
});
|
||||
|
||||
describe("formatUtcOffset", () => {
|
||||
it("renders signed HH:MM offsets, including quarter-hour zones", () => {
|
||||
expect(formatUtcOffset(0)).toBe("UTC+00:00");
|
||||
expect(formatUtcOffset(120)).toBe("UTC+02:00");
|
||||
expect(formatUtcOffset(-540)).toBe("UTC−09:00");
|
||||
expect(formatUtcOffset(345)).toBe("UTC+05:45"); // Nepal
|
||||
expect(formatUtcOffset(-270)).toBe("UTC−04:30");
|
||||
});
|
||||
|
||||
it("dashes on non-finite input", () => {
|
||||
expect(formatUtcOffset(NaN)).toBe("—");
|
||||
});
|
||||
});
|
||||
|
||||
@@ -0,0 +1,61 @@
|
||||
import { describe, it, expect } from "vitest";
|
||||
import { groupEventsByPhase } from "../../app/sessions/utils/eventHelpers";
|
||||
import type { EnrollmentEvent } from "@/types";
|
||||
|
||||
/**
|
||||
* Pins the P13 guardrail: the timeline orders by SEQUENCE, never by time. Sequence is a
|
||||
* persisted, strictly monotonic per-session counter assigned at emit time and immune to
|
||||
* every clock problem; the timestamp carries the device clock frame plus, for
|
||||
* CMTrace-derived events, the writer's timezone belief. A backdated line (the field case:
|
||||
* mdm_policy_reboot_required at −58 min amid live events) must stay at its sequence
|
||||
* position — the display marks the jump, the order never moves.
|
||||
*/
|
||||
|
||||
const PHASE_NAMES: Record<number, string> = { 0: "Unknown", 1: "Start" };
|
||||
const PHASE_ORDER = ["Start"];
|
||||
|
||||
function makeEvent(sequence: number, timestamp: string, phase = 0): EnrollmentEvent {
|
||||
return {
|
||||
eventId: `evt-${sequence}`,
|
||||
sessionId: "s",
|
||||
timestamp,
|
||||
eventType: "status_update",
|
||||
severity: "Info",
|
||||
source: "DecisionEngine",
|
||||
phase,
|
||||
message: "",
|
||||
sequence,
|
||||
};
|
||||
}
|
||||
|
||||
describe("groupEventsByPhase ordering", () => {
|
||||
it("orders strictly by sequence — a backdated timestamp never moves an event", () => {
|
||||
// Shuffled input; sequence 4 carries a timestamp 9 h EARLIER than its neighbors
|
||||
// (era-mixed CMTrace line). Time-based sorting would pull it to the front.
|
||||
const events = [
|
||||
makeEvent(5, "2026-08-20T10:05:00Z"),
|
||||
makeEvent(2, "2026-08-20T10:01:00Z"),
|
||||
makeEvent(4, "2026-08-20T01:03:00Z"), // backdated by ~9h, higher sequence
|
||||
makeEvent(1, "2026-08-20T10:00:00Z", 1),
|
||||
makeEvent(3, "2026-08-20T10:02:00Z"),
|
||||
];
|
||||
|
||||
const { eventsByPhase, orderedPhases } = groupEventsByPhase(events, PHASE_NAMES, PHASE_ORDER);
|
||||
|
||||
expect(orderedPhases).toEqual(["Start"]);
|
||||
expect(eventsByPhase["Start"].map(e => e.sequence)).toEqual([1, 2, 3, 4, 5]);
|
||||
});
|
||||
|
||||
it("uses the timestamp only as a tie-break for EQUAL sequence values", () => {
|
||||
// Equal sequences happen when the counter was not persisted across a reboot.
|
||||
const events = [
|
||||
makeEvent(1, "2026-08-20T10:00:00Z", 1),
|
||||
{ ...makeEvent(7, "2026-08-20T10:09:00Z"), eventId: "b" },
|
||||
{ ...makeEvent(7, "2026-08-20T10:07:00Z"), eventId: "a" },
|
||||
];
|
||||
|
||||
const { eventsByPhase } = groupEventsByPhase(events, PHASE_NAMES, PHASE_ORDER);
|
||||
|
||||
expect(eventsByPhase["Start"].map(e => e.eventId)).toEqual(["evt-1", "a", "b"]);
|
||||
});
|
||||
});
|
||||
@@ -0,0 +1,118 @@
|
||||
import { describe, it, expect } from "vitest";
|
||||
import {
|
||||
readTimeProvenance,
|
||||
classifyTimeJump,
|
||||
BACKWARD_JUMP_THRESHOLD_MS,
|
||||
type TimeJumpInput,
|
||||
} from "../timeProvenance";
|
||||
|
||||
const T0 = new Date("2026-08-20T10:00:00Z");
|
||||
const minutes = (m: number) => new Date(T0.getTime() + m * 60 * 1000);
|
||||
|
||||
function input(displayTime: Date, data?: Record<string, unknown>): TimeJumpInput {
|
||||
return { displayTime, provenance: readTimeProvenance(data) };
|
||||
}
|
||||
|
||||
describe("readTimeProvenance", () => {
|
||||
it("reads camelCase keys and parses numeric strings", () => {
|
||||
const p = readTimeProvenance({
|
||||
sourceLocalTs: "2026-08-20T05:31:46.5192284",
|
||||
sourceOffsetMinutes: "-540",
|
||||
sourceOffsetOrigin: "line-anchored",
|
||||
measuredWriterOffsetMinutes: "120",
|
||||
derivedTimestamp: "true",
|
||||
rejectedSourceTimestamp: "2026-08-13T09:00:00Z",
|
||||
});
|
||||
expect(p).not.toBeNull();
|
||||
expect(p!.sourceOffsetMinutes).toBe(-540);
|
||||
expect(p!.measuredWriterOffsetMinutes).toBe(120);
|
||||
expect(p!.sourceOffsetOrigin).toBe("line-anchored");
|
||||
expect(p!.derivedTimestamp).toBe("true");
|
||||
});
|
||||
|
||||
it("falls back to snake_case keys (historicReplay.ts convention)", () => {
|
||||
const p = readTimeProvenance({
|
||||
source_offset_minutes: "120",
|
||||
source_offset_origin: "reader-zone-fallback",
|
||||
});
|
||||
expect(p!.sourceOffsetMinutes).toBe(120);
|
||||
expect(p!.sourceOffsetOrigin).toBe("reader-zone-fallback");
|
||||
});
|
||||
|
||||
it("returns null when no provenance key is present (undefined data, truncated payload)", () => {
|
||||
expect(readTimeProvenance(undefined)).toBeNull();
|
||||
expect(readTimeProvenance(null)).toBeNull();
|
||||
expect(readTimeProvenance({})).toBeNull();
|
||||
// DataJson >30KB gets stored truncated; the UI then holds { _rawDataJson: "..." }.
|
||||
expect(readTimeProvenance({ _rawDataJson: '{"sourceOffsetMinutes":"120", …' })).toBeNull();
|
||||
expect(readTimeProvenance({ appId: "x", exitCode: "0" })).toBeNull();
|
||||
});
|
||||
|
||||
it("keeps partial provenance and nulls malformed numbers", () => {
|
||||
const p = readTimeProvenance({ sourceOffsetOrigin: "bias", sourceOffsetMinutes: "not-a-number" });
|
||||
expect(p).not.toBeNull();
|
||||
expect(p!.sourceOffsetOrigin).toBe("bias");
|
||||
expect(p!.sourceOffsetMinutes).toBeNull();
|
||||
expect(p!.sourceLocalTs).toBeNull();
|
||||
});
|
||||
|
||||
it("passes unknown origin strings through verbatim (forward compatibility)", () => {
|
||||
expect(readTimeProvenance({ sourceOffsetOrigin: "future-origin" })!.sourceOffsetOrigin).toBe("future-origin");
|
||||
});
|
||||
});
|
||||
|
||||
describe("classifyTimeJump", () => {
|
||||
it("pins the badge threshold at 5 minutes", () => {
|
||||
expect(BACKWARD_JUMP_THRESHOLD_MS).toBe(300_000);
|
||||
});
|
||||
|
||||
it("returns null without a previous rendered row", () => {
|
||||
expect(classifyTimeJump(null, input(T0))).toBeNull();
|
||||
});
|
||||
|
||||
it("ignores forward movement and sub-threshold backwards jitter", () => {
|
||||
expect(classifyTimeJump(input(T0), input(minutes(90)))).toBeNull();
|
||||
// 2 min backwards = interleaved-writer jitter inside the agent's grid tolerance.
|
||||
expect(classifyTimeJump(input(T0), input(minutes(-2)))).toBeNull();
|
||||
});
|
||||
|
||||
it("fires exactly at the threshold boundary", () => {
|
||||
expect(classifyTimeJump(input(T0), input(minutes(-5)))).toEqual({ deltaMs: 300_000, cause: null });
|
||||
expect(classifyTimeJump(input(T0), input(new Date(T0.getTime() - 299_999)))).toBeNull();
|
||||
});
|
||||
|
||||
it("names an era-mixed log when both rows carry differing applied offsets", () => {
|
||||
const prev = input(T0, { sourceOffsetMinutes: "120" });
|
||||
const curr = input(minutes(-540), { sourceOffsetMinutes: "-420" });
|
||||
expect(classifyTimeJump(prev, curr)).toEqual({ deltaMs: 540 * 60 * 1000, cause: "era-offset" });
|
||||
});
|
||||
|
||||
it("does not claim era-offset when either side lacks an offset", () => {
|
||||
const prev = input(T0);
|
||||
const curr = input(minutes(-540), { sourceOffsetMinutes: "-420" });
|
||||
expect(classifyTimeJump(prev, curr)!.cause).toBeNull();
|
||||
});
|
||||
|
||||
it("derivedTimestamp wins over era-offset (precedence)", () => {
|
||||
const prev = input(T0, { sourceOffsetMinutes: "120" });
|
||||
const curr = input(minutes(-540), { sourceOffsetMinutes: "-420", derivedTimestamp: "true" });
|
||||
expect(classifyTimeJump(prev, curr)!.cause).toBe("derived-timestamp");
|
||||
});
|
||||
|
||||
it("names a rejected source timestamp", () => {
|
||||
const curr = input(minutes(-30), { rejectedSourceTimestamp: "2026-08-13T09:00:00Z" });
|
||||
expect(classifyTimeJump(input(T0), curr)!.cause).toBe("rejected-source");
|
||||
});
|
||||
|
||||
it("classifies a week-old backdated replay with the correct magnitude", () => {
|
||||
const weekAgo = new Date(T0.getTime() - 7 * 24 * 60 * 60 * 1000);
|
||||
const jump = classifyTimeJump(input(T0), input(weekAgo));
|
||||
expect(jump).not.toBeNull();
|
||||
expect(jump!.deltaMs).toBe(7 * 24 * 60 * 60 * 1000);
|
||||
expect(jump!.cause).toBeNull();
|
||||
});
|
||||
|
||||
it("respects a caller-supplied threshold", () => {
|
||||
expect(classifyTimeJump(input(T0), input(minutes(-3)), 120_000)).toEqual({ deltaMs: 180_000, cause: null });
|
||||
});
|
||||
});
|
||||
@@ -50,3 +50,17 @@ export function formatPercent(numerator: number, denominator: number, decimals =
|
||||
if (!Number.isFinite(numerator) || !Number.isFinite(denominator) || denominator <= 0) return zero;
|
||||
return `${((numerator / denominator) * 100).toFixed(decimals)}%`;
|
||||
}
|
||||
|
||||
/**
|
||||
* Signed HH:MM UTC offset from a minutes value: 120 -> "UTC+02:00", -345 -> "UTC−05:45",
|
||||
* 0 -> "UTC+00:00". Quarter-hour zones (Nepal +05:45, Chatham +12:45) render exactly.
|
||||
* Non-finite returns `zero`.
|
||||
*/
|
||||
export function formatUtcOffset(minutes: number, zero = "—"): string {
|
||||
if (!Number.isFinite(minutes)) return zero;
|
||||
const sign = minutes < 0 ? "−" : "+";
|
||||
const abs = Math.abs(Math.round(minutes));
|
||||
const h = Math.floor(abs / 60);
|
||||
const m = abs % 60;
|
||||
return `UTC${sign}${String(h).padStart(2, "0")}:${String(m).padStart(2, "0")}`;
|
||||
}
|
||||
|
||||
@@ -0,0 +1,127 @@
|
||||
/**
|
||||
* CMTrace time-resolution provenance (P13): the agent's per-line self-anchoring stamps
|
||||
* CMTrace-derived events with how their UTC timestamp was produced — the raw local time
|
||||
* as written in the log, the applied UTC offset and its origin, the purely observational
|
||||
* per-file writer offset, and the clock-fallback markers. All values arrive as STRINGS
|
||||
* inside the event data payload (see docs/agent/cmtrace-time-resolution.md).
|
||||
*
|
||||
* The timeline sorts by sequence — always, never by time (user guardrail). A displayed
|
||||
* time that steps BACKWARDS within that order is therefore information, not a rendering
|
||||
* bug: a backdated log line, a staleness-clamp fallback, or an era-mixed log whose lines
|
||||
* were corrected with different offsets (session e9753578 carried ±9 h of exactly that).
|
||||
* `classifyTimeJump` names the phenomenon so the timeline can mark the spot instead of
|
||||
* leaving the reader to distrust the order.
|
||||
*/
|
||||
|
||||
export interface TimeProvenance {
|
||||
/** Raw local timestamp as written in the log line (no zone suffix, by design). */
|
||||
sourceLocalTs: string | null;
|
||||
/** UTC offset in minutes that was APPLIED to resolve the timestamp. */
|
||||
sourceOffsetMinutes: number | null;
|
||||
/** How the applied offset was obtained: "bias" | "line-anchored" | "reader-zone-fallback" | retired "calibrated". */
|
||||
sourceOffsetOrigin: string | null;
|
||||
/**
|
||||
* Observational per-file measurement from the writer's own UTC lines — NOT the applied
|
||||
* correction, and sticky after era flip-backs (the monotonicity guard rejects newer
|
||||
* anchors), so it can lag reality. Never present it as "what was applied".
|
||||
*/
|
||||
measuredWriterOffsetMinutes: number | null;
|
||||
/** "true" when the line's own timestamp was unusable and the agent clock was substituted. */
|
||||
derivedTimestamp: string | null;
|
||||
/** The line's own timestamp that the staleness clamp rejected (set alongside derivedTimestamp). */
|
||||
rejectedSourceTimestamp: string | null;
|
||||
}
|
||||
|
||||
function readString(data: Record<string, unknown>, camel: string, snake: string): string | null {
|
||||
const raw = data[camel] ?? data[snake];
|
||||
return typeof raw === "string" && raw.length > 0 ? raw : null;
|
||||
}
|
||||
|
||||
function readNumber(data: Record<string, unknown>, camel: string, snake: string): number | null {
|
||||
const raw = data[camel] ?? data[snake];
|
||||
if (typeof raw === "number") return Number.isFinite(raw) ? raw : null;
|
||||
if (typeof raw !== "string" || raw.length === 0) return null;
|
||||
const parsed = Number(raw);
|
||||
return Number.isFinite(parsed) ? parsed : null;
|
||||
}
|
||||
|
||||
/**
|
||||
* Reads the provenance fields from an event's data payload. Returns null when NO
|
||||
* provenance key is present — which also covers `data` being undefined and the
|
||||
* DataJson-truncation fallback (`_rawDataJson`), where the payload is not an object
|
||||
* of parsed keys at all.
|
||||
*/
|
||||
export function readTimeProvenance(data: Record<string, unknown> | undefined | null): TimeProvenance | null {
|
||||
if (!data || typeof data !== "object") return null;
|
||||
const provenance: TimeProvenance = {
|
||||
sourceLocalTs: readString(data, "sourceLocalTs", "source_local_ts"),
|
||||
sourceOffsetMinutes: readNumber(data, "sourceOffsetMinutes", "source_offset_minutes"),
|
||||
sourceOffsetOrigin: readString(data, "sourceOffsetOrigin", "source_offset_origin"),
|
||||
measuredWriterOffsetMinutes: readNumber(data, "measuredWriterOffsetMinutes", "measured_writer_offset_minutes"),
|
||||
derivedTimestamp: readString(data, "derivedTimestamp", "derived_timestamp"),
|
||||
rejectedSourceTimestamp: readString(data, "rejectedSourceTimestamp", "rejected_source_timestamp"),
|
||||
};
|
||||
const hasAny =
|
||||
provenance.sourceLocalTs !== null ||
|
||||
provenance.sourceOffsetMinutes !== null ||
|
||||
provenance.sourceOffsetOrigin !== null ||
|
||||
provenance.measuredWriterOffsetMinutes !== null ||
|
||||
provenance.derivedTimestamp !== null ||
|
||||
provenance.rejectedSourceTimestamp !== null;
|
||||
return hasAny ? provenance : null;
|
||||
}
|
||||
|
||||
/**
|
||||
* Row-badge threshold for a backwards step of the displayed time. Field-measured
|
||||
* (2026-08-20, 20 sessions): normal sessions max out at 0.6–1.7 min of interleaved-writer
|
||||
* jitter (the agent's own grid tolerance is 2 min), while every genuine offset phenomenon
|
||||
* starts at the 15-minute zone quantum. 5 min sits safely between the two — at this
|
||||
* threshold 12/12 normal sessions showed zero badges.
|
||||
*/
|
||||
export const BACKWARD_JUMP_THRESHOLD_MS = 5 * 60 * 1000;
|
||||
|
||||
export type TimeJumpCause = "era-offset" | "derived-timestamp" | "rejected-source" | null;
|
||||
|
||||
export interface TimeJump {
|
||||
/** Positive magnitude of the backwards step in milliseconds. */
|
||||
deltaMs: number;
|
||||
cause: TimeJumpCause;
|
||||
}
|
||||
|
||||
export interface TimeJumpInput {
|
||||
displayTime: Date;
|
||||
provenance: TimeProvenance | 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.
|
||||
* 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,
|
||||
): 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) {
|
||||
cause = "derived-timestamp";
|
||||
} else if (curr.provenance?.rejectedSourceTimestamp) {
|
||||
cause = "rejected-source";
|
||||
} else if (
|
||||
prev.provenance?.sourceOffsetMinutes !== null &&
|
||||
prev.provenance?.sourceOffsetMinutes !== undefined &&
|
||||
curr.provenance?.sourceOffsetMinutes !== null &&
|
||||
curr.provenance?.sourceOffsetMinutes !== undefined &&
|
||||
prev.provenance.sourceOffsetMinutes !== curr.provenance.sourceOffsetMinutes
|
||||
) {
|
||||
cause = "era-offset";
|
||||
}
|
||||
return { deltaMs, cause };
|
||||
}
|
||||
@@ -11,6 +11,10 @@ export interface EnrollmentEvent {
|
||||
sequence: number;
|
||||
receivedAt?: string;
|
||||
data?: Record<string, unknown>;
|
||||
/** True when ingest clamped an out-of-range device timestamp to server time. */
|
||||
timestampClamped?: boolean;
|
||||
/** The pre-clamp device timestamp; only set when timestampClamped is true. */
|
||||
originalTimestamp?: string | null;
|
||||
}
|
||||
|
||||
export interface RuleResult {
|
||||
|
||||
@@ -445,6 +445,7 @@ export const SHARED_MANIFEST = {
|
||||
],
|
||||
"analyzeRuleSources": [
|
||||
"app_install_duration",
|
||||
"clock_skew",
|
||||
"event_correlation",
|
||||
"event_count",
|
||||
"event_data",
|
||||
|
||||
@@ -441,6 +441,7 @@
|
||||
],
|
||||
"analyzeRuleSources": [
|
||||
"app_install_duration",
|
||||
"clock_skew",
|
||||
"event_correlation",
|
||||
"event_count",
|
||||
"event_data",
|
||||
|
||||
+37
@@ -0,0 +1,37 @@
|
||||
# CMTrace Log Fixtures — committed, anonymized
|
||||
|
||||
Raw CMTrace log lines, kept verbatim, used by parser and offset-calibration unit tests in
|
||||
`src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/`.
|
||||
|
||||
## Why this is a separate corpus from `../enrollment-sessions/`
|
||||
|
||||
`enrollment-sessions/` holds anonymized **DecisionSignal** JSONL replayed through the Replay
|
||||
Harness and the reducer scenario tests — signals that have already been parsed, adapted and
|
||||
evidence-tagged. These files are the layer *below* that: unparsed device log text, the raw input
|
||||
to `CmTraceLogParser`. They cannot satisfy that corpus's schema (no signal shape, no
|
||||
`Evidence.Identifier`, no terminal state to assert) and its category prefixes do not apply.
|
||||
|
||||
Both live under `tests/fixtures/` so committed test data has one home. Test projects must not
|
||||
carry their own fixture directories.
|
||||
|
||||
## Commit policy
|
||||
|
||||
1. **Anonymized.** No tenant IDs, device IDs, serial numbers, user names, UPN prefixes, raw IP
|
||||
addresses, or tenant-scoped object GUIDs (Intune policy/script IDs are tenant-scoped — replace
|
||||
them with `policy-anon-NNNN-0000-0000-0000-000000000000`). The all-zero GUID is a literal in
|
||||
IME's own output and stays. A session ID may stay when it is OUR diagnostic anchor and is
|
||||
already referenced from commit messages and `tasks/todo.md`.
|
||||
2. **Verbatim otherwise.** Timestamps, spacing and the `<![LOG[...]]LOG]!>` envelope are the point
|
||||
of the fixture — the parser is being tested against real formatting, so nothing else is
|
||||
normalised or reflowed.
|
||||
3. **Header comment.** State the source session, the agent version, and precisely which property
|
||||
the fixture exists to pin. A fixture whose purpose is not written down decays into noise.
|
||||
4. **Versioned filename.** `-vN` suffix; never edit a committed fixture in place — a test pinned
|
||||
to it would silently change meaning.
|
||||
5. **Extension `.cmtrace`,** not `.log`: `*.log` is globally gitignored.
|
||||
|
||||
## Fixtures
|
||||
|
||||
| File | Source | Pins |
|
||||
|---|---|---|
|
||||
| `agentexecutor-two-writer-eras-v1.cmtrace` | session `e9753578`, agent 2.0.1410, `ImeLogs/AgentExecutor.log` | One file containing TWO writer eras — 371 lines rendered at local hour 05 by a writer on PDT (UTC-7) and 195 at hour 14 by one already on CEST (UTC+2), nine hours apart, interleaved, no bias suffix on any line. The case that broke per-file offset calibration and forced revert `04b1a7c6`. Any era-aware calibrator must resolve BOTH halves correctly. |
|
||||
@@ -0,0 +1,41 @@
|
||||
# Real CMTrace lines from session e9753578-b1d8-4188-9151-7545be7e1761 (agent 2.0.1410).
|
||||
# ImeLogs/AgentExecutor.log - ONE file, TWO writer eras.
|
||||
#
|
||||
# The device booted on the Pacific OOBE default; the agent set W. Europe at 12:13:22Z.
|
||||
# Lines at local hour 05 were rendered by a writer still on PDT (UTC-7), lines at hour 14
|
||||
# by one already on CEST (UTC+2) - 9 hours apart, interleaved in the same log. No line
|
||||
# carries a bias suffix, so nothing in the file itself says which is which.
|
||||
#
|
||||
# This is the case that broke the per-file calibration: the anchor is the newest line, so
|
||||
# its offset was applied to the older era too. Any era-aware calibrator must resolve BOTH
|
||||
# halves of this file correctly.
|
||||
#
|
||||
# era PDT (local 05:xx): 371 lines in the original, era CEST (local 14:xx): 195
|
||||
|
||||
### --- transition window, verbatim ---
|
||||
<![LOG[ExecutorLog AgentExecutor gets invoked]LOG]!><time="14:13:36.8420339" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Creating command line parser, name delimiter is - and value separator is .]LOG]!><time="14:13:36.8460498" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Getting Ordered Parameters]LOG]!><time="14:13:36.8460498" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Parsing Ordered Parameters.]LOG]!><time="14:13:36.8484892" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Adding argument powershell with value C:\Program Files (x86)\Microsoft Intune Management Extension\Policies\Scripts\00000000-0000-0000-0000-000000000000_policy-anon-0001-0000-0000-0000-000000000000.ps1 to the named argument list.]LOG]!><time="14:13:36.8484892" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Powershell option gets invoked]LOG]!><time="14:13:36.8525204" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
|
||||
### --- additional PDT-era samples ---
|
||||
<![LOG[[Proxy Poller using ExectorLog] AgentExecutor log path : C:\ProgramData\Microsoft\IntuneManagementExtension\Logs\AgentExecutor.log]LOG]!><time="05:17:50.5238897" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="8" file="">
|
||||
<![LOG[[Proxy Poller using ExectorLog] AgentExecutor log path : C:\ProgramData\Microsoft\IntuneManagementExtension\Logs\AgentExecutor.log]LOG]!><time="05:17:50.5258992" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="8" file="">
|
||||
<![LOG[ExecutorLog AgentExecutor gets invoked]LOG]!><time="05:22:41.7798901" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Creating command line parser, name delimiter is - and value separator is .]LOG]!><time="05:22:41.7839044" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Getting Ordered Parameters]LOG]!><time="05:22:41.7859130" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Parsing Ordered Parameters.]LOG]!><time="05:22:41.7859130" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Adding argument powershell with value C:\Program Files (x86)\Microsoft Intune Management Extension\Policies\Scripts\policy-anon-0003-0000-0000-0000-000000000000_policy-anon-0002-0000-0000-0000-000000000000.ps1 to the named argument list.]LOG]!><time="05:22:41.7859130" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Powershell option gets invoked]LOG]!><time="05:22:41.7899258" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
|
||||
### --- additional CEST-era samples ---
|
||||
<![LOG[ExecutorLog AgentExecutor gets invoked]LOG]!><time="14:13:36.8420339" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Creating command line parser, name delimiter is - and value separator is .]LOG]!><time="14:13:36.8460498" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Getting Ordered Parameters]LOG]!><time="14:13:36.8460498" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Parsing Ordered Parameters.]LOG]!><time="14:13:36.8484892" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Adding argument powershell with value C:\Program Files (x86)\Microsoft Intune Management Extension\Policies\Scripts\00000000-0000-0000-0000-000000000000_policy-anon-0001-0000-0000-0000-000000000000.ps1 to the named argument list.]LOG]!><time="14:13:36.8484892" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Powershell option gets invoked]LOG]!><time="14:13:36.8525204" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[C:\Program Files (x86)\Microsoft Intune Management Extension\Policies\Scripts\00000000-0000-0000-0000-000000000000_policy-anon-0001-0000-0000-0000-000000000000.ps1]LOG]!><time="14:13:36.8545313" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[C:\Program Files (x86)\Microsoft Intune Management Extension\Policies\Results\00000000-0000-0000-0000-000000000000_policy-anon-0001-0000-0000-0000-000000000000.output]LOG]!><time="14:13:36.8545313" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
Reference in New Issue
Block a user