Compare commits

...

14 Commits

Author SHA1 Message Date
Oliver Kieselbach 2e20476559 feat(agent): extend RealmJoin timeout while first deployment is demonstrably active
The 60-min RealmJoinTimeout deadline arms at RJ detection (the RJ agent MSI
install during DeviceSetup) and used to cut off monitoring mid-install: report
55e6afd61c9d (session 46a96078) lost the tail of a large package catalog whose
last observed package completed 3 seconds before the deadline, with the first
deployment only starting 16 minutes into the window.

When the deadline now fires with LastDeploymentPhase 100/101 and deployment
activity (phase change or package observation, persisted restart-safe in
RealmJoinFacts.LastActivityUtc; the detection-time phase capture deliberately
does not count) inside the last 60 min, the handler re-arms to
lastActivity + 60 min instead of timing out — Info event
realmjoin_timeout_extended — clamped at an absolute cap of detection + 4 h.
realmjoin_timeout carries a reason payload (hard_timeout / inactivity /
absolute_cap); a fire of a deadline incarnation superseded by a re-arm
dead-ends via the OccurredAtUtc == DueAtUtc scheduler contract. The idle case
(no activity ever) still times out at 60 min, and phase-200/210 activity never
extends. Packages are only registry-visible at completion, so the inactivity
window keeps the full original 60 min.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
2026-08-21 01:11:48 +02:00
Oliver Kieselbach 990641b19e feat: P14 - per-upload-batch send time separates spool delay from clock offset
Agent stamps X-Send-Time-Utc (device clock, ISO-8601 round-trip) per upload
ATTEMPT; ingest parses it (year>=2000 guard, deliberately no upper clamp) and
server-stamps SentAt onto every event of the request. SentAt - OccurredUtc is
pure spool delay, ReceivedAt - SentAt is network + device-vs-server clock
offset - previously indistinguishable and only separable via median statistics.

clock_skew condition: batches carrying SentAt measure the frame directly
(spool-immune by construction - no spread cap, IME/clamped exclusions
irrelevant, IME-only sessions become measurable; evidence sentAtBatchCount);
legacy batches keep the per-event median path unchanged. CmTraceSkewTripwire
deliberately untouched: its differential median math cancels clock offset as
common mode.

Full persistence chain: Store x2 + Map, fields= projection (sentAt), MCP
get_session_events field list + rule-authoring-guide. New OKF doc
backend/send-time-frame-separation.md.

Suites: Functions 4370 (+16), Agent 2407 (+1), MCP vitest 564 + tsc 0.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
2026-08-21 00:44:29 +02:00
Oliver Kieselbach 3ca2f3b499 refactor(web): collapse time provenance behind an inline toggle
The labeled provenance rows duplicated values already visible in the
raw JSON dump and inflated the metadata block for every IME event. The
section is now collapsed by default behind a small "time provenance"
toggle sitting inline on the Created row (whose value it explains) -
zero extra height when collapsed, and the base label column returns to
its original width, so the default detail view is pixel-identical to
before P13. Expanding reveals the same rows, indented under Created.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
2026-08-21 00:02:26 +02:00
Oliver Kieselbach b9fa760404 feat(web): P13 - CMTrace time provenance visible in the session timeline
The per-line self-anchoring provenance (sourceLocalTs, applied offset +
origin, observational writer offset, derived/rejected markers) reaches
the browser but was buried unlabeled in the raw JSON dump. Sequence
stays THE sort order - without exception (now pinned by a regression
test); the corrected UTC is display-only, and a backwards step of the
displayed time within sequence order is marked as information instead
of confusing the reader.

- lib/timeProvenance.ts: readTimeProvenance (camelCase/snake_case,
  tolerant of truncated payloads) + classifyTimeJump with cause
  precedence derived > rejected-source > era-offset; era-offset
  requires applied offsets on BOTH rows - it never guesses.
- TimeJumpBadge on the row AFTER the jump, computed against the
  previous RENDERED row (filters/phase boundaries respected); sky for
  known causes, amber otherwise; tooltip carries both times, the delta
  and the "true write order (sequence)" sentence. Threshold 5 min,
  field-calibrated on 20 sessions: 12/12 normal sessions show zero
  badges, the era-mixed regression session shows exactly its 6.
- Clamped chip (rare) + TIME PROVENANCE detail section: only the
  applied offset says "(applied)"; the writer offset is explicitly
  observational (sticky after era flip-backs); origin chips with
  forward-compatible fallback for unknown values.
- EnrollmentEvent gains timestampClamped/originalTimestamp (wire
  already carried them); formatUtcOffset joins lib/formatting.

Verified: 814 web tests (19 new), tsc/eslint/build clean; Playwright
against e9753578 (badges match the pre-measurement), 9f475bb2 (no
badge on line-anchored rows, detail section correct, raw mode shows
exactly the one predicted jump).

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
2026-08-20 23:54:39 +02:00
Oliver Kieselbach ab61839685 feat(backend): P6 split - CMTrace skew tripwire + customer clock_skew rule
Operator side: CmTraceSkewTripwire piggybacks on the terminal counter
reconcile's partition scan (zero extra reads) and compares median
ReceivedAt-OccurredUtc deltas of IME-derived vs other events. A clean
15-min-grid divergence (residual < 2 min, >=20 samples / >=3 distinct
batches per side) emits the CmTraceTimeSkewRegression ops event
(Agent/Warning, goal: never fires). Bias-dominated sessions are
suppressed; measuredWriterOffsetMinutes is never consulted (sticky
after era flip-backs). Kill switch: CmTraceSkewTripwireDisabled.

Customer side: new clock_skew analyze condition source (skewMetric
clock_jump | sustained_offset, threshold seconds, gt/gte magnitude)
behind built-in ANALYZE-DEV-008 (300 s = the Kerberos/Entra 5-min skew
boundary). Batch-median frames with spool-spread filter, plateau step
detection (a gradual backlog-drain ramp cannot fake a jump) and
end-state persistence; IME-derived events are excluded so a CMTrace
anchoring regression can never fire the customer rule. Evidence carries
field=skewSummary/value for {{skewSummary}} interpolation.

Full mirroring chain: schema enum + skewMetric property, shared
manifest + combine.js regeneration, MCP authoring guide + semantic
lint, web SOURCES/form/card, ops-event dual-register, docs. P5 is
subsumed by the tripwire. PercentileMath is now the single nearest-rank
implementation (Apps/PlatformMetrics delegate).

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
2026-08-20 22:30:10 +02:00
Oliver Kieselbach 34fd40c3ad fix(agent): refuse cross-file calibration anchors, make rejections visible
Field forensics from the 1412 verification run (session 067797d8): the
label/anchor crossing recurred on a provably genuine binary, and the
new anchor-timestamp tripwire delivered — the "+02:00 measured for
IntuneManagementExtension.log" anchor (local 19:51:26.948) does not
exist in ANY log file on the device, and IME.log never produced its
expected first measurement during 24 s of growing passes beforehand.
Mechanism still unexplained; per-line anchoring keeps resolution
immune (all 58 line-anchored events of the session were correct), but
the observational layer must convict the culprit next time:

- CalibrateFrom now receives the iteration's ACTUAL file name next to
  the calibration key. A mismatch — the smoking gun the two field
  occurrences imply but static analysis says is impossible — logs a
  Warning with both names plus the anchor, and refuses the anchor, so
  even the unexplained path can no longer poison the measurement store.
- The first calibrator rejection per file logs at Debug (anchor local
  time + clock). The 24 s of silent non-measurement is exactly what
  made the phenomenon undiagnosable from the agent log.

232 IME tracker tests green against a verified-clean build.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
2026-08-20 20:18:35 +02:00
Oliver Kieselbach a0eb1b9e35 Merge branch 'main' of https://github.com/okieselbach/Autopilot-Monitor 2026-08-20 19:45:40 +02:00
Oliver Kieselbach 9d677db2a8 docs(okf): CMTrace time resolution — per-line self-anchoring concept
Why the reader-zone assumption and the per-file offset application both
failed, the per-line self-anchoring rule with its strict freshness
contract (LastCheckedUtc on every poll look, 30 s window, no freshness
across restarts), the provenance vocabulary that keeps every event
re-derivable, and the documented limits: the bounded grid-replay edge,
snapshot readers staying on the marked fallback, and the still-open
e9753578 label/anchor crossing with its tripwire.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
2026-08-20 19:28:54 +02:00
Oliver Kieselbach c728a0bd41 feat(backend): surface genuine agent binary-integrity mismatches as ops events
IntegrityCheckFailed emergency reports used to land in 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.
They now materialize as an AgentBinaryIntegrityMismatch ops event
(Warning, Agent category, dual-registered in the web alert-rule
catalog per feedback_ops_event_types_dual_register).

With suppression for the KNOWN, accepted release race the operator
correctly called out: around every release, agents compare against
hash snapshots that do not belong to their own binary — an older agent
sees the new release's hash on its next config fetch, and a freshly
installed latest agent can receive the PREVIOUS release's hashes from
the 5-minute AdminConfiguration cache (e9753578: genuine 1410 exe
checked against the cached 1409 hash — proven by the 1409 archive
logging "verified OK" with exactly that hash). Both self-heal via the
forced self-update and are suppressed at materialization time against
the CURRENT config: reported running hash == published exe, or
reported version != latest. 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 outside the release pipeline.
Missing config fails open to recording; visibility beats suppression.

Ops event only, deliberately no timeline event: the report is about
the binary, not the enrollment, and may precede session registration.

Backend suite 4320 green, web tsc clean.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
2026-08-20 19:28:43 +02:00
Oliver Kieselbach 64336c0c89 feat(agent): resolve fresh CMTrace lines by per-line self-anchoring
The era-aware successor to the reverted per-file offset application
(04b1a7c6). At a 100 ms poll, every line of a provably fresh pass was
written essentially "now", so its own distance to the agent clock,
rounded to the 15-minute offset grid, IS its writer's UTC offset — no
cross-line state, which is what interleaved writer eras break. The line
timestamp still contributes sub-poll precision and ordering; the grid
absorbs poll latency. Origin: LineAnchored → "line-anchored".

Freshness is stricter than "the file grew": every poll look stamps
LastCheckedUtc (empty first sights included, so AgentExecutor.log
anchors from its very first content), a pass anchors only when the gap
since the last look is ≤ 30 s (FreshLineMaxAge — far above the poll,
far below the 13-minute zone where a line's AGE rounds onto the grid),
and a restart-restored bookmark deliberately carries no freshness at
all — downtime backlog must never anchor. Everything not provably
fresh keeps the uniform reader-zone fallback: wrong in absolute terms,
self-consistent for durations, and marked as such (the revert's core
lesson — partially corrected is strictly worse than uniformly wrong).

Accepted, bounded edge (characterization test): a freshly WRITTEN line
carrying a replayed timestamp aged exactly N×15 min ± 2 min anchors to
≈now — an anchored line lands at now ± 2 min by construction, and
sub-24h replays are treated as current by the historic-replay guard.

The per-file measurement stays observational (Info log +
measuredWriterOffsetMinutes) and now logs the anchor's local timestamp
as a tripwire: session e9753578 logged "+02:00 measured for
IntuneManagementExtension.log" although that file provably held no
+2-era line — a label/anchor pairing the committed code could not be
shown to produce (iteration-local anchor, single sequential call site,
green repro of the exact field scenario, no +2-capable chunk in the
window). The mechanism remains open; the resolution path is immune to
it by design, and CmTraceCalibratorFileIsolationTests pins the file
isolation so a real regression can never ship silently.

Tests: 13 new — resolves-to-T across five writer beliefs, interleaved
eras inside one chunk, first-sight/empty-first-sight/poll-gap/restart
freshness boundaries (including the nastiest backlog: exactly 30 min
old, on-grid), the grid-replay edge, and the committed two-writer-era
fixture replayed at production poll cadence across its write silences.
Agent suite 2406 green against a verified-clean build.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
2026-08-20 19:28:27 +02:00
Oliver Kieselbach 59c944618b test(agent): move CMTrace fixture to tests/fixtures and anonymize it
Two corrections to 3c25172d, both found by asking why the repo suddenly had two
fixture locations.

Location: committed test data lives under tests/fixtures/. I had put this one
inside the agent test project without checking, creating a second parallel home.
It does NOT belong in tests/fixtures/enrollment-sessions/ either — that is a
governed corpus of anonymized DecisionSignal JSONL for the Replay Harness, with a
schema, category prefixes and a paired-scenario-test rule that raw log text cannot
satisfy. So: a sibling corpus, tests/fixtures/cmtrace-logs/, with its own README
stating why it is separate.

Anonymization: the fixture carried three real Intune policy/script GUIDs from a
customer tenant. Point 1 of the existing fixture policy requires tenant-scoped
identifiers to be replaced, and I committed without applying it — the check
belonged BEFORE the commit, not after. Replaced with
policy-anon-NNNN-0000-0000-0000-000000000000, consistent with the tenant-anon /
device-anon / user-anon convention already in use. The all-zero GUID is a literal
in IME's own output and stays; the session ID stays as our diagnostic anchor and
is already referenced from the commit history and tasks/todo.md.

The new README carries the commit policy for this corpus, including the rules that
were implicit before: verbatim content (the parser is tested against real
formatting), a header stating what the fixture pins, versioned filenames so a
pinned test cannot silently change meaning, and .cmtrace rather than .log because
*.log is globally gitignored.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-08-20 17:54:55 +02:00
Oliver Kieselbach 3c25172dfb test(agent): real two-writer-era CMTrace fixture from session e9753578
Captured from ImeLogs/AgentExecutor.log of the session that exposed the regression
(agent 2.0.1410; device booted on the Pacific OOBE default, agent set W. Europe at
12:13:22Z).

One file, two writer eras: 371 lines rendered at local hour 05 by a writer still
on PDT (UTC-7) and 195 at hour 14 by one already on CEST (UTC+2) - nine hours
apart, interleaved, and no line carries a bias suffix, so nothing in the file
itself says which is which. Exactly the case the per-file calibration could not
express, and the test that was missing.

Analysing the archive also turned up a SECOND, independent defect the revert
commit did not know about: the agent log reports "IntuneManagementExtension.log
writer offset measured 02:00:00" while that file contains ONLY hour-05 lines
(2022 of them, zero at hour 14). A +2 measurement is impossible from its own
content, so the calibration anchor leaked across file boundaries - files are
walked in sorted order and AgentExecutor.log precedes it. Two-eras-per-file and
anchor-leak are separate bugs; both must be fixed.

Extension is .cmtrace.txt, not .log: *.log is globally gitignored, and a fixture
has no reason to claim that extension.

Fixture only, nothing consumes it yet - the era-aware calibrator is next.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-08-20 17:47:15 +02:00
Oliver Kieselbach eda61eaade Fix Tenant Groups layout overflowing on phones (#132) 2026-08-20 15:27:08 +02:00
Oliver Kieselbach 04b1a7c6e7 revert(agent): stop applying the measured CMTrace offset — one offset per file is wrong
Field regression, session e9753578 (agent 2.0.1410, PST-defaulted device in DE).
Five script_started events resolved 9 h early while their script_completed
counterparts resolved correctly, inflating every platform-script duration to
~32,400 s. Reverts the application introduced in e9dba11b.

Root cause: calibration keeps ONE offset per log file, but a single file can hold
lines from two writer eras. IME restarting across a timezone change leaves older
lines in the old zone and newer ones in the new zone, in the same file. The anchor
is the newest line, so its offset was also applied to the older lines, for which
it does not hold. The class doc even claimed "self-healing on writer restart" —
that reasoning only ever covered FUTURE lines, never the ones already on disk.

The more expensive mistake was the second one: correcting ABSOLUTE timestamps
without checking what depends on their DIFFERENCES. Applying the reader zone
uniformly is wrong in absolute terms but self-consistent — both ends of a duration
are wrong by the same amount, so the duration is right. Correcting only some
timestamps produced a mixed frame inside one session, which is strictly worse than
being uniformly wrong. This is the same asymmetry the original analysis described
for AppInstallSummaries (68 min reported against 8 min real) and then reproduced.

What stays, deliberately:
- Bias-carrying lines still resolve via the writer-declared offset; that path was
  never implicated.
- The measurement keeps running. It costs nothing, feeds the Info log, and is the
  field data the era-aware fix has to be built on — the first anlauf got the era
  question wrong from assumption rather than observation.
- Provenance now separates measured from applied (measuredWriterOffsetMinutes vs
  sourceOffsetMinutes). The broken event was tagged "calibrated" while carrying an
  offset that did not hold for its line; that confusion must not be expressible.
- The fallback path reports the offset it actually applied. An event stating no
  offset cannot be recomputed later, which defeats the point of provenance.

Provenance earned its keep here: 57 events measured -420 (the PDT writer) against
5 at +120 made the diagnosis a two-minute query instead of median statistics over
a session.

Next: era-aware calibration keyed on the IME-STARTED marker, which we already
track, plus a test over a log file containing two writer eras — the case that was
missing.

Agent 2393 green against a verified-clean build.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-08-20 14:31:50 +02:00
70 changed files with 4078 additions and 182 deletions
+127
View File
@@ -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).
+19 -1
View File
@@ -143,11 +143,29 @@ advisory backstop. All routes converge on `CompleteThroughFinalizingOrDefer`:
first-deployment window 100/101 for 200/210 without 110 — the RJ ESP was aborted,
typically by an interactive logon reclassifying the run as secondary-user; emits
the `realmjoin_first_deployment_incomplete` Warning, session 224b2087), and
`Timeout` (hard 60-min deadline). The abort rule reads the *persisted*
`Timeout` (60-min deadline from detection). The abort rule reads the *persisted*
`RealmJoinFacts.LastDeploymentPhase` (updated by the typed `RealmJoinPhaseChanged`
signal), so it survives agent restarts — the `RealmJoinDetected` replay path
evaluates it too. A first observation of 210 does **not** release (RJ may have
completed before agent boot and deploy afterwards).
**Activity-based timeout extension** (report 55e6afd61c9d — a large RJ package
catalog outlived the 60-min window mid-install): when the timeout deadline fires
while the first deployment is demonstrably active — `LastDeploymentPhase` 100/101
*and* deployment activity (`RealmJoinPhaseChanged` or a package observation, tracked
in `RealmJoinFacts.LastActivityUtc`; the phase captured at detection deliberately
does not count) within the last 60 min — the handler re-arms the deadline to
`lastActivity + 60 min` instead of timing out, emitting an Info
`realmjoin_timeout_extended` event. Re-arms clamp to an absolute cap of
**detection + 4 h**. Package activity is only observable at package *completion*
(RJ writes the registry subkey when the install finishes), so a single install
that is registry-silent for over 60 min still times out — the eventual
`realmjoin_timeout` carries a `reason` payload (`hard_timeout` / `inactivity` /
`absolute_cap`) telling the three shapes apart. A stale fire of an older deadline
incarnation (armed due later than the fire time; `OccurredAtUtc = DueAtUtc` per
scheduler contract) dead-ends as `realmjoin_timeout_stale_superseded_by_rearm`.
The idle case (detected, no deployment activity ever) times out at 60 min
unchanged, and phase 200/210 activity never extends.
2. `Finalizing` stage + ~5 s `FinalizingGrace` deadline.
3. Grace fires → `Completed`, `EnrollmentComplete` outcome, `enrollment_complete`
timeline event with full audit payload.
@@ -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.
+2
View File
@@ -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.
+10
View File
@@ -1,7 +1,17 @@
# Log
## 2026-08-21
* **Update**: `agent/decision-engine.md` — activity-based RealmJoin timeout extension (report 55e6afd61c9d: a large RJ package catalog outlived the 60-min window mid-install — the timer arms at RJ-agent-MSI detection, so the first deployment had effectively ~44 min). When the `RealmJoinTimeout` deadline fires with `LastDeploymentPhase` 100/101 and deployment activity (phase change or package observation, persisted in `RealmJoinFacts.LastActivityUtc`; the detection-time phase capture deliberately excluded) inside the last 60 min, the deadline re-arms to `lastActivity + 60 min` (Info event `realmjoin_timeout_extended`), clamped at detection + 4 h. `realmjoin_timeout` now carries `reason` = `hard_timeout` / `inactivity` / `absolute_cap`; a fire of a superseded deadline incarnation dead-ends. Idle detection and phase-200/210 sessions keep the original 60-min behavior.
* **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
+69
View File
@@ -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
View File
@@ -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",
+6 -1
View File
@@ -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",
@@ -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();
}
}
}
}
@@ -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;
}
}
@@ -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]
@@ -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]
@@ -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))
@@ -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; }
@@ -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";
}
}
@@ -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
{
@@ -372,6 +372,9 @@ namespace AutopilotMonitor.DecisionCore.Tests
// Before RealmJoinPhaseChanged became a typed signal, LastDeploymentPhase was only
// written at detection time — every realmjoin_timeout claimed "last phase: 0" no
// matter how far RJ actually got, hiding this whole failure class from ops.
// Since the activity-based extension, the PhaseChanged at T0+6 counts as activity,
// so the first fire (59 min later) extends once; the timeout lands on the re-armed
// fire a full inactivity window after the last activity.
var engine = new DecisionEngine();
var state = PrimeClassicAwaitingDesktop(engine);
state = engine.Reduce(state, MakeSignal(5, DecisionSignalKind.RealmJoinDetected, T0.AddMinutes(5),
@@ -384,7 +387,13 @@ namespace AutopilotMonitor.DecisionCore.Tests
})).NewState;
state = engine.Reduce(state, MakeSignal(7, DecisionSignalKind.DesktopArrived, T0.AddMinutes(7))).NewState;
var step = engine.Reduce(state, MakeSignal(8, DecisionSignalKind.DeadlineFired, T0.AddMinutes(65),
// First fire at the original due (T0+65): activity 59 min ago → extends to T0+66.
state = engine.Reduce(state, MakeSignal(8, DecisionSignalKind.DeadlineFired, T0.AddMinutes(65),
new Dictionary<string, string> { [SignalPayloadKeys.Deadline] = DeadlineNames.RealmJoinTimeout })).NewState;
var rearmed = Assert.Single(state.Deadlines, d => d.Name == DeadlineNames.RealmJoinTimeout);
Assert.Equal(T0.AddMinutes(66), rearmed.DueAtUtc);
var step = engine.Reduce(state, MakeSignal(9, DecisionSignalKind.DeadlineFired, rearmed.DueAtUtc,
new Dictionary<string, string> { [SignalPayloadKeys.Deadline] = DeadlineNames.RealmJoinTimeout }));
var timeout = Assert.Single(step.Effects, e =>
@@ -395,6 +404,248 @@ namespace AutopilotMonitor.DecisionCore.Tests
Assert.Equal("101", timeout.Parameters["lastSeenPhase"]);
}
// ============================================================== Activity-based extension (report 55e6afd61c9d)
[Fact]
public void Timeout_fire_with_recent_first_deployment_activity_extends_instead_of_timing_out()
{
// Report 55e6afd61c9d (Douglas): timer armed at detection (phase 0, RJ agent MSI
// install during DeviceSetup), first deployment only started 16 min later, Office
// completed 3 s before the deadline — the hard cut truncated an actively working
// deployment. The fire must now re-arm to lastActivity + 60 min instead.
var engine = new DecisionEngine();
var state = PrimeClassicAwaitingDesktop(engine);
state = engine.Reduce(state, MakeSignal(5, DecisionSignalKind.RealmJoinDetected, T0.AddMinutes(5),
new Dictionary<string, string> { [DecisionEngine.RealmJoinPayloadKeys.DeploymentPhase] = "0" })).NewState;
state = engine.Reduce(state, MakeSignal(6, DecisionSignalKind.DesktopArrived, T0.AddMinutes(6))).NewState;
state = engine.Reduce(state, MakeSignal(7, DecisionSignalKind.RealmJoinPhaseChanged, T0.AddMinutes(21),
new Dictionary<string, string>
{
[DecisionEngine.RealmJoinPayloadKeys.DeploymentPhase] = "101",
[DecisionEngine.RealmJoinPayloadKeys.PreviousPhase] = "0",
})).NewState;
state = engine.Reduce(state, MakeSignal(8, DecisionSignalKind.RealmJoinPackageCompleted, T0.AddMinutes(62),
new Dictionary<string, string>
{
[DecisionEngine.RealmJoinPayloadKeys.PackageId] = "generic-microsoft-office-2016-proplus",
[DecisionEngine.RealmJoinPayloadKeys.Scope] = RealmJoinPackageFact.ScopeMachine,
[DecisionEngine.RealmJoinPayloadKeys.Success] = "true",
[DecisionEngine.RealmJoinPayloadKeys.LastExitCode] = "0",
})).NewState;
var armed = Assert.Single(state.Deadlines, d => d.Name == DeadlineNames.RealmJoinTimeout);
var step = engine.Reduce(state, MakeSignal(9, DecisionSignalKind.DeadlineFired, armed.DueAtUtc,
new Dictionary<string, string> { [SignalPayloadKeys.Deadline] = DeadlineNames.RealmJoinTimeout }));
// No completion, no outcome — the gate stays closed and the window is re-armed.
Assert.NotEqual(SessionStage.Finalizing, step.NewState.Stage);
Assert.Null(step.NewState.RealmJoinFacts.Outcome);
Assert.Equal($"DeadlineFired:{DeadlineNames.RealmJoinTimeout}:Extended", step.Transition.Trigger);
var rearmed = Assert.Single(step.NewState.Deadlines, d => d.Name == DeadlineNames.RealmJoinTimeout);
Assert.Equal(T0.AddMinutes(62 + 60), rearmed.DueAtUtc); // lastActivity + inactivity window
Assert.Single(step.Effects, e =>
e.Kind == DecisionEffectKind.ScheduleDeadline &&
e.Deadline != null &&
e.Deadline.Name == DeadlineNames.RealmJoinTimeout &&
e.Deadline.DueAtUtc == rearmed.DueAtUtc);
var extended = Assert.Single(step.Effects, e =>
e.Kind == DecisionEffectKind.EmitEventTimelineEntry &&
e.Parameters != null &&
e.Parameters.TryGetValue("eventType", out var et) && et == "realmjoin_timeout_extended");
Assert.Equal("Info", extended.Parameters!["severity"]);
Assert.Equal("101", extended.Parameters["deploymentPhase"]);
Assert.DoesNotContain(step.Effects, e =>
e.Kind == DecisionEffectKind.EmitEventTimelineEntry &&
e.Parameters != null &&
e.Parameters.TryGetValue("eventType", out var et) && et == "realmjoin_timeout");
}
[Fact]
public void Resolved_after_extension_completes_via_classic_path()
{
var engine = new DecisionEngine();
var state = PrimeClassicAwaitingDesktop(engine);
state = engine.Reduce(state, MakeSignal(5, DecisionSignalKind.RealmJoinDetected, T0.AddMinutes(5),
new Dictionary<string, string> { [DecisionEngine.RealmJoinPayloadKeys.DeploymentPhase] = "101" })).NewState;
state = engine.Reduce(state, MakeSignal(6, DecisionSignalKind.DesktopArrived, T0.AddMinutes(6))).NewState;
state = engine.Reduce(state, MakeSignal(7, DecisionSignalKind.RealmJoinPhaseChanged, T0.AddMinutes(40),
new Dictionary<string, string>
{
[DecisionEngine.RealmJoinPayloadKeys.DeploymentPhase] = "100",
[DecisionEngine.RealmJoinPayloadKeys.PreviousPhase] = "101",
})).NewState;
var armed = Assert.Single(state.Deadlines, d => d.Name == DeadlineNames.RealmJoinTimeout);
state = engine.Reduce(state, MakeSignal(8, DecisionSignalKind.DeadlineFired, armed.DueAtUtc,
new Dictionary<string, string> { [SignalPayloadKeys.Deadline] = DeadlineNames.RealmJoinTimeout })).NewState;
Assert.Null(state.RealmJoinFacts.Outcome); // extended, not timed out
var step = engine.Reduce(state, MakeSignal(9, DecisionSignalKind.RealmJoinResolved, T0.AddMinutes(80),
new Dictionary<string, string> { [DecisionEngine.RealmJoinPayloadKeys.DeploymentPhase] = "110" }));
Assert.Equal(SessionStage.Finalizing, step.NewState.Stage);
Assert.Equal("Resolved", step.NewState.RealmJoinFacts.Outcome!.Value);
Assert.DoesNotContain(step.NewState.Deadlines, d => d.Name == DeadlineNames.RealmJoinTimeout);
}
[Fact]
public void Rearmed_fire_after_quiet_window_times_out_with_inactivity_reason()
{
var engine = new DecisionEngine();
var state = PrimeClassicAwaitingDesktop(engine);
state = engine.Reduce(state, MakeSignal(5, DecisionSignalKind.RealmJoinDetected, T0.AddMinutes(5),
new Dictionary<string, string> { [DecisionEngine.RealmJoinPayloadKeys.DeploymentPhase] = "0" })).NewState;
state = engine.Reduce(state, MakeSignal(6, DecisionSignalKind.DesktopArrived, T0.AddMinutes(6))).NewState;
state = engine.Reduce(state, MakeSignal(7, DecisionSignalKind.RealmJoinPhaseChanged, T0.AddMinutes(30),
new Dictionary<string, string>
{
[DecisionEngine.RealmJoinPayloadKeys.DeploymentPhase] = "101",
[DecisionEngine.RealmJoinPayloadKeys.PreviousPhase] = "0",
})).NewState;
var armed = Assert.Single(state.Deadlines, d => d.Name == DeadlineNames.RealmJoinTimeout);
state = engine.Reduce(state, MakeSignal(8, DecisionSignalKind.DeadlineFired, armed.DueAtUtc,
new Dictionary<string, string> { [SignalPayloadKeys.Deadline] = DeadlineNames.RealmJoinTimeout })).NewState;
var rearmed = Assert.Single(state.Deadlines, d => d.Name == DeadlineNames.RealmJoinTimeout);
Assert.Equal(T0.AddMinutes(90), rearmed.DueAtUtc); // lastActivity (T0+30) + 60 min
// No further activity — the re-armed fire must now time out for real.
var step = engine.Reduce(state, MakeSignal(9, DecisionSignalKind.DeadlineFired, rearmed.DueAtUtc,
new Dictionary<string, string> { [SignalPayloadKeys.Deadline] = DeadlineNames.RealmJoinTimeout }));
Assert.Equal(SessionStage.Finalizing, step.NewState.Stage);
Assert.Equal("Timeout", step.NewState.RealmJoinFacts.Outcome!.Value);
var timeout = Assert.Single(step.Effects, e =>
e.Kind == DecisionEffectKind.EmitEventTimelineEntry &&
e.Parameters != null &&
e.Parameters.TryGetValue("eventType", out var et) && et == "realmjoin_timeout");
Assert.Equal("inactivity", timeout.Parameters!["reason"]);
Assert.Contains("no deployment activity", timeout.Parameters["message"]);
}
[Fact]
public void Extension_is_capped_at_absolute_ceiling_and_cap_fire_times_out_despite_activity()
{
// Late activity pushes the sliding window beyond detection + 4 h — the re-arm must
// clamp to the cap, and the cap fire must time out even though activity is recent.
var engine = new DecisionEngine();
var state = PrimeClassicAwaitingDesktop(engine);
state = engine.Reduce(state, MakeSignal(5, DecisionSignalKind.RealmJoinDetected, T0.AddMinutes(5),
new Dictionary<string, string> { [DecisionEngine.RealmJoinPayloadKeys.DeploymentPhase] = "101" })).NewState;
state = engine.Reduce(state, MakeSignal(6, DecisionSignalKind.DesktopArrived, T0.AddMinutes(6))).NewState;
// Package completion whose sliding window (T0+230+60) would exceed the cap (T0+245).
state = engine.Reduce(state, MakeSignal(7, DecisionSignalKind.RealmJoinPackageCompleted, T0.AddMinutes(230),
new Dictionary<string, string>
{
[DecisionEngine.RealmJoinPayloadKeys.PackageId] = "generic-big-suite",
[DecisionEngine.RealmJoinPayloadKeys.Scope] = RealmJoinPackageFact.ScopeMachine,
[DecisionEngine.RealmJoinPayloadKeys.Success] = "true",
[DecisionEngine.RealmJoinPayloadKeys.LastExitCode] = "0",
})).NewState;
var armed = Assert.Single(state.Deadlines, d => d.Name == DeadlineNames.RealmJoinTimeout);
state = engine.Reduce(state, MakeSignal(8, DecisionSignalKind.DeadlineFired, armed.DueAtUtc,
new Dictionary<string, string> { [SignalPayloadKeys.Deadline] = DeadlineNames.RealmJoinTimeout })).NewState;
var rearmed = Assert.Single(state.Deadlines, d => d.Name == DeadlineNames.RealmJoinTimeout);
Assert.Equal(T0.AddMinutes(5).AddHours(4), rearmed.DueAtUtc); // clamped to detection + cap
var step = engine.Reduce(state, MakeSignal(9, DecisionSignalKind.DeadlineFired, rearmed.DueAtUtc,
new Dictionary<string, string> { [SignalPayloadKeys.Deadline] = DeadlineNames.RealmJoinTimeout }));
Assert.Equal(SessionStage.Finalizing, step.NewState.Stage);
Assert.Equal("Timeout", step.NewState.RealmJoinFacts.Outcome!.Value);
var timeout = Assert.Single(step.Effects, e =>
e.Kind == DecisionEffectKind.EmitEventTimelineEntry &&
e.Parameters != null &&
e.Parameters.TryGetValue("eventType", out var et) && et == "realmjoin_timeout");
Assert.Equal("absolute_cap", timeout.Parameters!["reason"]);
}
[Fact]
public void Stale_fire_of_old_incarnation_after_rearm_is_dead_end()
{
// Race: the OLD deadline incarnation's fire was already queued when the extension
// re-armed. The armed deadline is due LATER than the stale fire — dead-end, no
// second extension evaluation, no timeout.
var engine = new DecisionEngine();
var state = PrimeClassicAwaitingDesktop(engine);
state = engine.Reduce(state, MakeSignal(5, DecisionSignalKind.RealmJoinDetected, T0.AddMinutes(5),
new Dictionary<string, string> { [DecisionEngine.RealmJoinPayloadKeys.DeploymentPhase] = "0" })).NewState;
state = engine.Reduce(state, MakeSignal(6, DecisionSignalKind.RealmJoinPhaseChanged, T0.AddMinutes(30),
new Dictionary<string, string>
{
[DecisionEngine.RealmJoinPayloadKeys.DeploymentPhase] = "101",
[DecisionEngine.RealmJoinPayloadKeys.PreviousPhase] = "0",
})).NewState;
var armed = Assert.Single(state.Deadlines, d => d.Name == DeadlineNames.RealmJoinTimeout);
state = engine.Reduce(state, MakeSignal(7, DecisionSignalKind.DeadlineFired, armed.DueAtUtc,
new Dictionary<string, string> { [SignalPayloadKeys.Deadline] = DeadlineNames.RealmJoinTimeout })).NewState;
Assert.Null(state.RealmJoinFacts.Outcome); // extended
var step = engine.Reduce(state, MakeSignal(8, DecisionSignalKind.DeadlineFired, armed.DueAtUtc,
new Dictionary<string, string> { [SignalPayloadKeys.Deadline] = DeadlineNames.RealmJoinTimeout }));
Assert.False(step.Transition.Taken);
Assert.Null(step.NewState.RealmJoinFacts.Outcome);
Assert.Empty(step.Effects);
var stillArmed = Assert.Single(step.NewState.Deadlines, d => d.Name == DeadlineNames.RealmJoinTimeout);
Assert.Equal(T0.AddMinutes(90), stillArmed.DueAtUtc);
}
[Fact]
public void Detection_phase_alone_is_not_activity_idle_case_times_out_at_60_min_unchanged()
{
// The phase captured AT detection must not count as activity — RJ detected in a
// first-deployment phase that then never moves still times out after the original
// 60 min (the extension exists for demonstrable progress, not for standing still).
var engine = new DecisionEngine();
var state = PrimeClassicAwaitingDesktop(engine);
state = engine.Reduce(state, MakeSignal(5, DecisionSignalKind.RealmJoinDetected, T0.AddMinutes(5),
new Dictionary<string, string> { [DecisionEngine.RealmJoinPayloadKeys.DeploymentPhase] = "101" })).NewState;
state = engine.Reduce(state, MakeSignal(6, DecisionSignalKind.DesktopArrived, T0.AddMinutes(6))).NewState;
Assert.Null(state.RealmJoinFacts.LastActivityUtc);
var armed = Assert.Single(state.Deadlines, d => d.Name == DeadlineNames.RealmJoinTimeout);
var step = engine.Reduce(state, MakeSignal(7, DecisionSignalKind.DeadlineFired, armed.DueAtUtc,
new Dictionary<string, string> { [SignalPayloadKeys.Deadline] = DeadlineNames.RealmJoinTimeout }));
Assert.Equal(SessionStage.Finalizing, step.NewState.Stage);
Assert.Equal("Timeout", step.NewState.RealmJoinFacts.Outcome!.Value);
var timeout = Assert.Single(step.Effects, e =>
e.Kind == DecisionEffectKind.EmitEventTimelineEntry &&
e.Parameters != null &&
e.Parameters.TryGetValue("eventType", out var et) && et == "realmjoin_timeout");
Assert.Equal("hard_timeout", timeout.Parameters!["reason"]);
}
[Fact]
public void Regular_deployment_phase_with_activity_does_not_extend()
{
// Session 6f1959c0 shape: RJ stood at 210 when the agent booted and deploys
// regular (non-first) packages afterwards. Phase 200/210 is outside the
// first-deployment window — activity there must NOT hold the session hostage.
var engine = new DecisionEngine();
var state = PrimeClassicAwaitingDesktop(engine);
state = engine.Reduce(state, MakeSignal(5, DecisionSignalKind.RealmJoinDetected, T0.AddMinutes(5),
new Dictionary<string, string> { [DecisionEngine.RealmJoinPayloadKeys.DeploymentPhase] = "210" })).NewState;
state = engine.Reduce(state, MakeSignal(6, DecisionSignalKind.DesktopArrived, T0.AddMinutes(6))).NewState;
state = engine.Reduce(state, MakeSignal(7, DecisionSignalKind.RealmJoinPhaseChanged, T0.AddMinutes(40),
new Dictionary<string, string>
{
[DecisionEngine.RealmJoinPayloadKeys.DeploymentPhase] = "200",
[DecisionEngine.RealmJoinPayloadKeys.PreviousPhase] = "210",
})).NewState;
var armed = Assert.Single(state.Deadlines, d => d.Name == DeadlineNames.RealmJoinTimeout);
var step = engine.Reduce(state, MakeSignal(8, DecisionSignalKind.DeadlineFired, armed.DueAtUtc,
new Dictionary<string, string> { [SignalPayloadKeys.Deadline] = DeadlineNames.RealmJoinTimeout }));
Assert.Equal(SessionStage.Finalizing, step.NewState.Stage);
Assert.Equal("Timeout", step.NewState.RealmJoinFacts.Outcome!.Value);
}
[Fact]
public void SelfDeploying_deferred_terminal_released_by_first_deployment_incomplete()
{
@@ -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
/// &lt; 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()
{
@@ -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=&lt;sha256&gt;, expected=&lt;sha256&gt;". 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
@@ -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] = {
@@ -121,6 +121,7 @@ export const EVENT_TYPES_CATALOG = {
'realmjoin_phase_changed',
'realmjoin_resolved',
'realmjoin_timeout',
'realmjoin_timeout_extended',
'realmjoin_first_deployment_incomplete',
'realmjoin_package_started',
'realmjoin_package_completed',
@@ -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()
@@ -151,6 +151,10 @@ namespace AutopilotMonitor.DecisionCore.Engine
{
data["realmjoinReleaseChannel"] = postState.RealmJoinFacts.ReleaseChannel.Value;
}
if (postState.RealmJoinFacts.LastActivityUtc != null)
{
data["realmjoinLastActivityUtc"] = FormatUtc(postState.RealmJoinFacts.LastActivityUtc.Value);
}
data["realmjoinPackages"] = BuildRealmJoinPackageSummary(postState.RealmJoinFacts.Packages);
}
@@ -11,16 +11,30 @@ namespace AutopilotMonitor.DecisionCore.Engine
// RealmJoin (RJ) deployment-tracking handlers. Plan: tasks/zany-gathering-oasis plan.
// The agent posts six DecisionSignalKinds when it observes the
// HKLM\SYSTEM\CurrentControlSet\Services\realmjoin\Parameters key + HKLM\SOFTWARE\RealmJoin\Packages
// (and the HKU\<sid>\... user-scope counterpart). Detection arms a 60-min hard timeout
// (and the HKU\<sid>\... user-scope counterpart). Detection arms a 60-min timeout
// and gates the enrollment-completion AND-gate. Resolution (phase 110), the
// aborted-first-deployment release (phase left 100/101 for 200/210 without 110 —
// session 224b2087) or the timeout releases the gate so the session can complete.
// When the timeout fires while the first deployment is demonstrably still active
// (phase 100/101 with deployment activity inside the last 60 min), the deadline is
// re-armed instead — up to an absolute 4-h cap from detection (report 55e6afd61c9d:
// a large package catalog outlived the 60-min window mid-install).
public sealed partial class DecisionEngine
{
// Hard 60-minute deadline from RJ-detected. Not configurable (per design choice —
// the trigger is intentionally aggressive, the timeout has to bound it).
// 60-minute deadline from RJ-detected. Not configurable (per design choice —
// the trigger is intentionally aggressive, the timeout has to bound it). Doubles
// as the inactivity window for the activity-based extension: RJ package writes are
// only observable at package COMPLETION (RJ creates the registry subkey when the
// install finishes), so a single long install is registry-silent for its whole
// duration and the window must not be tightened below the original 60 min.
private static readonly TimeSpan s_realmJoinHardTimeout = TimeSpan.FromMinutes(60);
// Absolute ceiling for activity-based extensions, measured from RJ detection.
// Preserves the original design intent (the aggressive detection trigger stays
// bounded) and sits safely inside AgentMaxLifetimeMinutes (360) — the agent's own
// lifetime watchdog would otherwise be the only backstop.
private static readonly TimeSpan s_realmJoinAbsoluteTimeout = TimeSpan.FromHours(4);
// Payload keys consumed by the new handlers (set by the agent's RealmJoinWatcherAdapter).
// Public because the V2.Core agent adapter assembles signal payloads with these keys.
public static class RealmJoinPayloadKeys
@@ -64,14 +78,16 @@ namespace AutopilotMonitor.DecisionCore.Engine
|| facts.Outcome != null;
/// <summary>
/// Build the 60-min RJ hard-timeout deadline. Floored at <see cref="DecisionState.AgentBootUtc"/>
/// via <see cref="EffectiveDeadlineBase"/> so a replayed RealmJoinDetected signal cannot
/// collapse the timer into immediate-fire at boot.
/// Build the RJ timeout deadline for an explicit due time. Initial arm: detection
/// (floored at <see cref="DecisionState.AgentBootUtc"/> via <see cref="EffectiveDeadlineBase"/>
/// so a replayed RealmJoinDetected signal cannot collapse the timer into immediate-fire
/// at boot) + 60 min. Re-arm (activity-based extension): last activity + 60 min,
/// capped at detection + 4 h.
/// </summary>
private static ActiveDeadline BuildRealmJoinTimeoutDeadline(DateTime fromUtc) =>
private static ActiveDeadline BuildRealmJoinTimeoutDeadline(DateTime dueAtUtc) =>
new ActiveDeadline(
name: DeadlineNames.RealmJoinTimeout,
dueAtUtc: fromUtc.Add(s_realmJoinHardTimeout),
dueAtUtc: dueAtUtc,
firesSignalKind: DecisionSignalKind.DeadlineFired,
firesPayload: new Dictionary<string, string>
{
@@ -134,7 +150,8 @@ namespace AutopilotMonitor.DecisionCore.Engine
var effects = Array.Empty<DecisionEffect>();
if (!alreadyDetected)
{
var deadline = BuildRealmJoinTimeoutDeadline(EffectiveDeadlineBase(state, signal));
var deadline = BuildRealmJoinTimeoutDeadline(
EffectiveDeadlineBase(state, signal).Add(s_realmJoinHardTimeout));
builder.AddDeadline(deadline);
effects = new[]
{
@@ -224,13 +241,20 @@ namespace AutopilotMonitor.DecisionCore.Engine
private DecisionStep HandleRealmJoinTimeoutDeadlineFired(DecisionState state, DecisionSignal signal)
{
var alreadyResolvedOrTimedOut = state.RealmJoinFacts.Outcome != null;
var deadlineStillArmed = false;
ActiveDeadline? armedDeadline = null;
foreach (var d in state.Deadlines)
{
if (d.Name == DeadlineNames.RealmJoinTimeout) { deadlineStillArmed = true; break; }
if (d.Name == DeadlineNames.RealmJoinTimeout) { armedDeadline = d; break; }
}
if (alreadyResolvedOrTimedOut || !deadlineStillArmed)
// Third staleness shape (introduced with the activity-based extension): the fire
// belongs to an OLDER deadline incarnation that a re-arm has since replaced —
// recognizable because the armed deadline is due LATER than this fire
// (OccurredAtUtc = DueAtUtc per the scheduler contract). Without this guard the
// stale fire would evaluate the timeout/extension decision ahead of schedule.
var supersededByRearm = armedDeadline != null && armedDeadline.DueAtUtc > signal.OccurredAtUtc;
if (alreadyResolvedOrTimedOut || armedDeadline == null || supersededByRearm)
{
var bookkept = BumpStepBookkeeping(state, signal);
var staleTransition = BuildDeadEndTransition(
@@ -240,12 +264,60 @@ namespace AutopilotMonitor.DecisionCore.Engine
trigger: $"DeadlineFired:{DeadlineNames.RealmJoinTimeout}",
deadEndReason: alreadyResolvedOrTimedOut
? "realmjoin_timeout_stale_outcome_already_set"
: "realmjoin_timeout_stale_deadline_not_armed");
: armedDeadline == null
? "realmjoin_timeout_stale_deadline_not_armed"
: "realmjoin_timeout_stale_superseded_by_rearm");
return new DecisionStep(bookkept, staleTransition, Array.Empty<DecisionEffect>());
}
var nextStep = state.StepIndex + 1;
// Activity-based extension (report 55e6afd61c9d): when the first deployment is
// demonstrably still active — phase 100/101 with deployment activity (phase change
// or package observation) inside the last 60 min — re-arm instead of cutting off
// mid-install. Bounded by an absolute 4-h cap from detection so the original
// "aggressive trigger stays bounded" design intent survives. The idle case
// (detected, but the first deployment never produced any activity) is unchanged:
// LastActivityUtc stays null and the 60-min timeout fires exactly as before.
var facts = state.RealmJoinFacts;
var now = signal.OccurredAtUtc;
var lastActivity = facts.LastActivityUtc?.Value;
var detectedUtc = facts.DetectedUtc?.Value;
var inFirstDeployment = facts.LastDeploymentPhase != null
&& IsRealmJoinFirstDeploymentPhase(facts.LastDeploymentPhase.Value);
var recentActivity = lastActivity != null && now - lastActivity.Value < s_realmJoinHardTimeout;
var withinCap = detectedUtc != null && now - detectedUtc.Value < s_realmJoinAbsoluteTimeout;
if (inFirstDeployment && recentActivity && withinCap)
{
var windowDue = lastActivity!.Value.Add(s_realmJoinHardTimeout);
var capDue = detectedUtc!.Value.Add(s_realmJoinAbsoluteTimeout);
var newDue = windowDue < capDue ? windowDue : capDue;
var rearm = BuildRealmJoinTimeoutDeadline(newDue);
var rearmBuilder = state.ToBuilder()
.WithStepIndex(nextStep)
.WithLastAppliedSignalOrdinal(signal.SessionSignalOrdinal)
.CancelDeadline(DeadlineNames.RealmJoinTimeout)
.AddDeadline(rearm);
var rearmState = rearmBuilder.Build();
var rearmTransition = BuildTakenTransition(
before: state,
signal: signal,
toStage: state.Stage,
nextStepIndex: nextStep,
trigger: $"DeadlineFired:{DeadlineNames.RealmJoinTimeout}:Extended");
var rearmEffects = new[]
{
new DecisionEffect(DecisionEffectKind.ScheduleDeadline, deadline: rearm),
BuildRealmJoinTimeoutExtendedEvent(facts, lastActivity.Value, newDue),
};
return new DecisionStep(rearmState, rearmTransition, rearmEffects);
}
var builder = state.ToBuilder()
.WithStepIndex(nextStep)
.WithLastAppliedSignalOrdinal(signal.SessionSignalOrdinal)
@@ -253,7 +325,15 @@ namespace AutopilotMonitor.DecisionCore.Engine
builder.RealmJoinFacts = state.RealmJoinFacts.WithTimeoutOutcome(signal.SessionSignalOrdinal);
var timeoutEffect = BuildRealmJoinTimeoutEvent(state);
// Message differentiates WHY the gate gave up: absolute cap exhausted while still
// active, activity went quiet, or the original hard timeout (no activity ever seen).
var reason = inFirstDeployment && recentActivity && !withinCap
? RealmJoinTimeoutReasonAbsoluteCap
: inFirstDeployment && lastActivity != null
? RealmJoinTimeoutReasonInactivity
: RealmJoinTimeoutReasonHardTimeout;
var timeoutEffect = BuildRealmJoinTimeoutEvent(state, reason);
return CompleteIfDeferredOrBookkeep(
state: state,
@@ -331,7 +411,9 @@ namespace AutopilotMonitor.DecisionCore.Engine
var builder = state.ToBuilder()
.WithStepIndex(nextStep)
.WithLastAppliedSignalOrdinal(signal.SessionSignalOrdinal);
builder.RealmJoinFacts = state.RealmJoinFacts.WithLastPhase(currentPhase.Value, signal.SessionSignalOrdinal);
builder.RealmJoinFacts = state.RealmJoinFacts
.WithLastPhase(currentPhase.Value, signal.SessionSignalOrdinal)
.WithActivity(signal.OccurredAtUtc, signal.SessionSignalOrdinal);
if (!IsFirstDeploymentAbortTransition(state.RealmJoinFacts, previousPhase, currentPhase.Value))
{
@@ -442,12 +524,14 @@ namespace AutopilotMonitor.DecisionCore.Engine
var builder = state.ToBuilder()
.WithStepIndex(nextStep)
.WithLastAppliedSignalOrdinal(signal.SessionSignalOrdinal);
builder.RealmJoinFacts = state.RealmJoinFacts.WithPackageStarted(
packageId: packageId!,
displayName: displayName,
version: version,
scope: scope,
startedUtc: signal.OccurredAtUtc);
builder.RealmJoinFacts = state.RealmJoinFacts
.WithPackageStarted(
packageId: packageId!,
displayName: displayName,
version: version,
scope: scope,
startedUtc: signal.OccurredAtUtc)
.WithActivity(signal.OccurredAtUtc, signal.SessionSignalOrdinal);
var newState = builder.Build();
var transition = BuildTakenTransition(
@@ -490,14 +574,16 @@ namespace AutopilotMonitor.DecisionCore.Engine
var builder = state.ToBuilder()
.WithStepIndex(nextStep)
.WithLastAppliedSignalOrdinal(signal.SessionSignalOrdinal);
builder.RealmJoinFacts = state.RealmJoinFacts.WithPackageCompleted(
packageId: packageId!,
displayName: displayName,
version: version,
scope: scope,
completedUtc: signal.OccurredAtUtc,
success: success,
lastExitCode: lastExitCode);
builder.RealmJoinFacts = state.RealmJoinFacts
.WithPackageCompleted(
packageId: packageId!,
displayName: displayName,
version: version,
scope: scope,
completedUtc: signal.OccurredAtUtc,
success: success,
lastExitCode: lastExitCode)
.WithActivity(signal.OccurredAtUtc, signal.SessionSignalOrdinal);
var newState = builder.Build();
var transition = BuildTakenTransition(
@@ -654,6 +740,15 @@ namespace AutopilotMonitor.DecisionCore.Engine
return null;
}
// Reason strings carried in the realmjoin_timeout event payload ("reason") and
// reflected in its message. HardTimeout = original semantics (no deployment activity
// ever observed, 60 min from detection); Inactivity = the first deployment produced
// activity at some point but went quiet for a full 60-min window; AbsoluteCap = still
// active but the 4-h extension ceiling from detection is exhausted.
internal const string RealmJoinTimeoutReasonHardTimeout = "hard_timeout";
internal const string RealmJoinTimeoutReasonInactivity = "inactivity";
internal const string RealmJoinTimeoutReasonAbsoluteCap = "absolute_cap";
/// <summary>
/// Build the <c>realmjoin_timeout</c> timeline-entry effect emitted by the deadline-
/// fired handler. Unlike <see cref="DecisionSignalKind.RealmJoinDetected"/> /
@@ -661,7 +756,7 @@ namespace AutopilotMonitor.DecisionCore.Engine
/// InformationalEvent), the timeout is a synthetic deadline so the reducer owns its
/// timeline visibility.
/// </summary>
private static DecisionEffect BuildRealmJoinTimeoutEvent(DecisionState state)
private static DecisionEffect BuildRealmJoinTimeoutEvent(DecisionState state, string reason)
{
var facts = state.RealmJoinFacts;
var lastPhase = facts.LastDeploymentPhase?.Value ?? 0;
@@ -672,17 +767,60 @@ namespace AutopilotMonitor.DecisionCore.Engine
if (facts.Packages[i].CompletedUtc != null) completed++;
}
var message = reason == RealmJoinTimeoutReasonAbsoluteCap
? $"RealmJoin did not reach phase 110 within {(int)s_realmJoinAbsoluteTimeout.TotalHours} h of detection (last phase: {lastPhase}) — monitoring window exhausted despite recent deployment activity."
: reason == RealmJoinTimeoutReasonInactivity
? $"RealmJoin did not reach phase 110 — no deployment activity for {(int)s_realmJoinHardTimeout.TotalMinutes} min (last phase: {lastPhase})."
: $"RealmJoin did not reach phase 110 within {(int)s_realmJoinHardTimeout.TotalMinutes} min (last phase: {lastPhase}).";
return new DecisionEffect(
kind: DecisionEffectKind.EmitEventTimelineEntry,
parameters: new Dictionary<string, string>(StringComparer.Ordinal)
{
[SignalPayloadKeys.EventType] = SharedConstants.EventTypes.RealmJoinTimeout,
[SignalPayloadKeys.Source] = "DecisionEngine",
[SignalPayloadKeys.Severity] = "Warning",
[SignalPayloadKeys.Message] = message,
["lastSeenPhase"] = lastPhase.ToString(CultureInfo.InvariantCulture),
["packagesTracked"] = tracked.ToString(CultureInfo.InvariantCulture),
["packagesCompleted"] = completed.ToString(CultureInfo.InvariantCulture),
["reason"] = reason,
});
}
/// <summary>
/// Build the <c>realmjoin_timeout_extended</c> timeline-entry effect emitted when the
/// timeout deadline fires but the first deployment is demonstrably still active and
/// the monitoring window is re-armed instead. Reducer-owned like
/// <see cref="BuildRealmJoinTimeoutEvent"/> (synthetic deadline, no agent dual-emit).
/// </summary>
private static DecisionEffect BuildRealmJoinTimeoutExtendedEvent(
RealmJoinFacts facts,
DateTime lastActivityUtc,
DateTime newDueUtc)
{
var lastPhase = facts.LastDeploymentPhase?.Value ?? 0;
var tracked = facts.Packages.Count;
var completed = 0;
for (var i = 0; i < facts.Packages.Count; i++)
{
if (facts.Packages[i].CompletedUtc != null) completed++;
}
return new DecisionEffect(
kind: DecisionEffectKind.EmitEventTimelineEntry,
parameters: new Dictionary<string, string>(StringComparer.Ordinal)
{
[SignalPayloadKeys.EventType] = SharedConstants.EventTypes.RealmJoinTimeout,
[SignalPayloadKeys.EventType] = SharedConstants.EventTypes.RealmJoinTimeoutExtended,
[SignalPayloadKeys.Source] = "DecisionEngine",
[SignalPayloadKeys.Severity] = "Warning",
[SignalPayloadKeys.Message] = $"RealmJoin did not reach phase 110 within 60 min (last phase: {lastPhase}).",
["lastSeenPhase"] = lastPhase.ToString(CultureInfo.InvariantCulture),
[SignalPayloadKeys.Severity] = "Info",
[SignalPayloadKeys.Message] =
$"RealmJoin first deployment still active (phase {lastPhase}, {completed}/{tracked} packages completed, last activity {lastActivityUtc:HH:mm:ss} UTC) — extending monitoring window to {newDueUtc:HH:mm:ss} UTC (cap {(int)s_realmJoinAbsoluteTimeout.TotalHours} h after detection).",
["deploymentPhase"] = lastPhase.ToString(CultureInfo.InvariantCulture),
["packagesTracked"] = tracked.ToString(CultureInfo.InvariantCulture),
["packagesCompleted"] = completed.ToString(CultureInfo.InvariantCulture),
["lastActivityUtc"] = lastActivityUtc.ToString("O", CultureInfo.InvariantCulture),
["extendedUntilUtc"] = newDueUtc.ToString("O", CultureInfo.InvariantCulture),
});
}
@@ -39,7 +39,8 @@ namespace AutopilotMonitor.DecisionCore.State
selfDeployingDeferredCompletion: null,
productVersion: null,
releaseChannel: null,
packages: Array.Empty<RealmJoinPackageFact>());
packages: Array.Empty<RealmJoinPackageFact>(),
lastActivityUtc: null);
public RealmJoinFacts(
SignalFact<DateTime>? detectedUtc,
@@ -49,7 +50,8 @@ namespace AutopilotMonitor.DecisionCore.State
SignalFact<bool>? selfDeployingDeferredCompletion,
SignalFact<string>? productVersion,
SignalFact<string>? releaseChannel,
IReadOnlyList<RealmJoinPackageFact> packages)
IReadOnlyList<RealmJoinPackageFact> packages,
SignalFact<DateTime>? lastActivityUtc = null)
{
DetectedUtc = detectedUtc;
ResolvedUtc = resolvedUtc;
@@ -59,6 +61,7 @@ namespace AutopilotMonitor.DecisionCore.State
ProductVersion = productVersion;
ReleaseChannel = releaseChannel;
Packages = packages ?? Array.Empty<RealmJoinPackageFact>();
LastActivityUtc = lastActivityUtc;
}
/// <summary>First-observation timestamp of the <c>HKLM\SYSTEM\...\realmjoin\Parameters</c> key.</summary>
@@ -98,6 +101,15 @@ namespace AutopilotMonitor.DecisionCore.State
/// <summary>Tracked per-package install rows (machine + user scope combined).</summary>
public IReadOnlyList<RealmJoinPackageFact> Packages { get; }
/// <summary>
/// Most recent observed RJ deployment activity: a <c>RealmJoinPhaseChanged</c> or a
/// per-package started/completed observation. Deliberately NOT set at detection time —
/// the RJ-detected-but-never-deploying idle case must still hit the 60-min hard
/// timeout unchanged. Drives the activity-based timeout extension (report 55e6afd61c9d:
/// the hard timeout cut off a demonstrably active first deployment mid-install).
/// </summary>
public SignalFact<DateTime>? LastActivityUtc { get; }
public RealmJoinFacts WithDetected(DateTime utc, long sourceSignalOrdinal)
{
if (DetectedUtc != null) return this; // set-once
@@ -109,7 +121,8 @@ namespace AutopilotMonitor.DecisionCore.State
selfDeployingDeferredCompletion: SelfDeployingDeferredCompletion,
productVersion: ProductVersion,
releaseChannel: ReleaseChannel,
packages: Packages);
packages: Packages,
lastActivityUtc: LastActivityUtc);
}
/// <summary>
@@ -129,7 +142,8 @@ namespace AutopilotMonitor.DecisionCore.State
selfDeployingDeferredCompletion: SelfDeployingDeferredCompletion,
productVersion: new SignalFact<string>(productVersion, sourceSignalOrdinal),
releaseChannel: ReleaseChannel,
packages: Packages);
packages: Packages,
lastActivityUtc: LastActivityUtc);
}
/// <summary>
@@ -149,7 +163,8 @@ namespace AutopilotMonitor.DecisionCore.State
selfDeployingDeferredCompletion: SelfDeployingDeferredCompletion,
productVersion: ProductVersion,
releaseChannel: new SignalFact<string>(releaseChannel, sourceSignalOrdinal),
packages: Packages);
packages: Packages,
lastActivityUtc: LastActivityUtc);
}
public RealmJoinFacts WithResolved(DateTime utc, int phase, long sourceSignalOrdinal)
@@ -163,7 +178,8 @@ namespace AutopilotMonitor.DecisionCore.State
selfDeployingDeferredCompletion: SelfDeployingDeferredCompletion,
productVersion: ProductVersion,
releaseChannel: ReleaseChannel,
packages: Packages);
packages: Packages,
lastActivityUtc: LastActivityUtc);
}
/// <summary>
@@ -184,7 +200,28 @@ namespace AutopilotMonitor.DecisionCore.State
selfDeployingDeferredCompletion: SelfDeployingDeferredCompletion,
productVersion: ProductVersion,
releaseChannel: ReleaseChannel,
packages: Packages);
packages: Packages,
lastActivityUtc: LastActivityUtc);
}
/// <summary>
/// Record an RJ deployment-activity observation (phase change or package event).
/// Monotonic — an earlier or equal timestamp (replayed signal) is a no-op, so the
/// activity fact can never move backwards.
/// </summary>
public RealmJoinFacts WithActivity(DateTime utc, long sourceSignalOrdinal)
{
if (LastActivityUtc != null && LastActivityUtc.Value >= utc) return this;
return new RealmJoinFacts(
detectedUtc: DetectedUtc,
resolvedUtc: ResolvedUtc,
lastDeploymentPhase: LastDeploymentPhase,
outcome: Outcome,
selfDeployingDeferredCompletion: SelfDeployingDeferredCompletion,
productVersion: ProductVersion,
releaseChannel: ReleaseChannel,
packages: Packages,
lastActivityUtc: new SignalFact<DateTime>(utc, sourceSignalOrdinal));
}
public RealmJoinFacts WithLastPhase(int phase, long sourceSignalOrdinal)
@@ -198,7 +235,8 @@ namespace AutopilotMonitor.DecisionCore.State
selfDeployingDeferredCompletion: SelfDeployingDeferredCompletion,
productVersion: ProductVersion,
releaseChannel: ReleaseChannel,
packages: Packages);
packages: Packages,
lastActivityUtc: LastActivityUtc);
}
public RealmJoinFacts WithTimeoutOutcome(long sourceSignalOrdinal)
@@ -212,7 +250,8 @@ namespace AutopilotMonitor.DecisionCore.State
selfDeployingDeferredCompletion: SelfDeployingDeferredCompletion,
productVersion: ProductVersion,
releaseChannel: ReleaseChannel,
packages: Packages);
packages: Packages,
lastActivityUtc: LastActivityUtc);
}
public RealmJoinFacts WithSelfDeployingDeferred(long sourceSignalOrdinal)
@@ -226,7 +265,8 @@ namespace AutopilotMonitor.DecisionCore.State
selfDeployingDeferredCompletion: new SignalFact<bool>(true, sourceSignalOrdinal),
productVersion: ProductVersion,
releaseChannel: ReleaseChannel,
packages: Packages);
packages: Packages,
lastActivityUtc: LastActivityUtc);
}
/// <summary>
@@ -246,7 +286,8 @@ namespace AutopilotMonitor.DecisionCore.State
selfDeployingDeferredCompletion: null,
productVersion: ProductVersion,
releaseChannel: ReleaseChannel,
packages: Packages);
packages: Packages,
lastActivityUtc: LastActivityUtc);
}
/// <summary>
@@ -301,7 +342,8 @@ namespace AutopilotMonitor.DecisionCore.State
selfDeployingDeferredCompletion: SelfDeployingDeferredCompletion,
productVersion: ProductVersion,
releaseChannel: ReleaseChannel,
packages: copy);
packages: copy,
lastActivityUtc: LastActivityUtc);
}
/// <summary>
@@ -370,7 +412,8 @@ namespace AutopilotMonitor.DecisionCore.State
selfDeployingDeferredCompletion: SelfDeployingDeferredCompletion,
productVersion: ProductVersion,
releaseChannel: ReleaseChannel,
packages: copy);
packages: copy,
lastActivityUtc: LastActivityUtc);
}
}
}
@@ -512,12 +512,17 @@ namespace AutopilotMonitor.Shared
// RealmJoin (RJ) deployment tracking — driven by HKLM\SYSTEM\...\realmjoin\Parameters
// + HKLM/HKU \SOFTWARE\RealmJoin\Packages\<id>. Detection extends the V2 enrollment
// session lifetime until DeploymentPhase reaches CompletedFirstDeployment (110) or
// the 60-min hard timeout fires. Per-package events surface install lifecycle in
// the 60-min timeout fires. Per-package events surface install lifecycle in
// the same shape as IME app_install_started / app_install_completed.
public const string RealmJoinDetected = "realmjoin_detected";
public const string RealmJoinPhaseChanged = "realmjoin_phase_changed";
public const string RealmJoinResolved = "realmjoin_resolved";
public const string RealmJoinTimeout = "realmjoin_timeout";
// Info: the timeout deadline fired while the first deployment was demonstrably
// still active (phase 100/101, deployment activity inside the last 60 min) —
// the monitoring window was re-armed instead of timing out (capped at 4 h from
// detection). Report 55e6afd61c9d.
public const string RealmJoinTimeoutExtended = "realmjoin_timeout_extended";
// Warning: DeploymentPhase left the first-deployment window (100/101) for 200/210
// without CompletedFirstDeployment (110) — the RJ ESP was aborted (typically an
// interactive logon during the first deployment reclassified the run as
@@ -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>{" "}
@@ -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&apos;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&apos;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",
@@ -607,6 +608,7 @@ export const SHARED_MANIFEST = {
"realmjoin_phase_changed",
"realmjoin_resolved",
"realmjoin_timeout",
"realmjoin_timeout_extended",
"reboot_triggered",
"registry_app_baseline",
"registry_app_state",
@@ -441,6 +441,7 @@
],
"analyzeRuleSources": [
"app_install_duration",
"clock_skew",
"event_correlation",
"event_count",
"event_data",
@@ -603,6 +604,7 @@
"realmjoin_phase_changed",
"realmjoin_resolved",
"realmjoin_timeout",
"realmjoin_timeout_extended",
"reboot_triggered",
"registry_app_baseline",
"registry_app_state",
+37
View File
@@ -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="">