Compare commits

...

16 Commits

Author SHA1 Message Date
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
Oliver Kieselbach 3b59dab2df feat(agent): carry timestamp provenance on IME-derived events
Every IME-sourced event now states what the writer wrote, what offset was applied,
and how that offset was obtained:

  sourceLocalTs       raw local time, verbatim, NO zone suffix
  sourceOffsetMinutes the offset subtracted
  sourceOffsetOrigin  bias | calibrated | reader-zone-fallback

Why: until now the only record of a conversion was the converted value, so a wrong
offset was indistinguishable from a right one. Proving the field defect needed the
diagnostics archive — and of the 5,386 sessions that went through a timezone
change, essentially none had one, so the analysis had to fall back to median
statistics across thousands of sessions to establish what one stored value makes
obvious per session. It also makes a stored timestamp recomputable after the fact,
without an agent release.

No zone suffix on sourceLocalTs on purpose: the value genuinely carries none, and
formatting one in would re-introduce the assumption this whole change removes.

sourceOffsetMinutes is normalised to one sense (local = UTC + offset) across both
origins. The wire bias uses the opposite GetTimeZoneInformation convention
(UTC = local + bias), so a "+480" line is reported as -480; without that the field
would flip sign depending on where the offset came from and be useless to compare.

Added centrally in TagDerivedTimestamp, which all 14 emit sites already call, so
this does not scatter through the adapter. DataJson only — no table schema change,
so no Store/Map/seed chain and no backend deploy needed to start collecting it.

Agent 2393 / backend 4313 green against a verified-clean build.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-08-20 14:05:32 +02:00
Oliver Kieselbach 389426f8f2 fix(agent): future-skew guard that a one-hour timezone error can actually trip
ResolveOccurredAt rejected a source timestamp when ageHours < -1.0. That bound
could not fire for the single most common timezone error: with a one-hour offset
mistake the real value is parseLag - 3600 s, i.e. just ABOVE -1.0. It sat exactly
on the boundary of the case it was meant to catch, which is why every skewed
session sailed past it.

It was asymmetric too — a past-shifted error had to exceed 24 h before anything
noticed, while the measured field errors reached -17 h.

The bound is now derived rather than guessed: writer and reader share one system
clock, and the tracker only sees a line after it was written, so a correctly
converted source timestamp is always at or behind "now". Anything ahead means the
conversion was wrong. MaxFutureSourceSkew is 2 minutes of jitter tolerance —
deliberately far below the hour a timezone mistake produces.

The rejection log now names which bound tripped and by how much, instead of
printing a bare ageHours that reads the same for both directions.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-08-20 14:05:31 +02:00
Oliver Kieselbach e9dba11b96 fix(agent): resolve IME log timestamps with the writer's measured offset
This is the behaviour change the previous two commits prepared. ImeLogTracker no
longer substitutes its own timezone belief for the IME process's; it measures the
writer's offset from a freshly appended line and converts with that.

Freshness is stricter than "the file grew". GetSafePosition returns 0 for an
unknown file, so the first pass reads the whole file and its newest line may be
hours old — anchoring there would measure the line's age, not the writer's offset.
LogFilePositionTracker.HasSeen(), captured BEFORE GetSafePosition creates the
entry, gates calibration on growth against a size we had already observed.

Calibration runs at the END of a qualifying pass, so that pass still uses the
previously measured offset — at most one poll (100 ms) old, and an offset only
moves when a process restarts. Calibrating first would mean buffering the pass,
which is not viable: the first pass over AppWorkload.log can be hundreds of MB.
The cost is a warm-up of one growing pass, during which lines fall back to the
reader zone.

Bias-carrying lines are never used as anchors: they already state the writer's
offset, so they need no measurement and must not overwrite one.

CalibrateFrom logs at Info when the measured offset disagrees with this process's
own zone, naming the correction applied. That disagreement is precisely the
condition that silently corrupted every IME-derived timestamp until now; agreement
stays at Debug so the normal case does not add noise.

Tests are deliberately machine-independent: the assertion is always "a line
written at instant T resolves to T", asserted across writer beliefs of +2, +1, 0,
-7 and +10. That one property covers both field cases — the writer disagreeing
with us (the bug) and the writer agreeing with us (the majority of sessions, where
two stale beliefs cancel and which a fix to the agent's own cache would have
broken). Plus: no calibration on first sight, following a writer restart into a
new zone, and a declared bias honoured without being measured.

CheckLogFilesAsync is internal as a test seam — calibration depends on the pass
structure, which only a real read cycle exercises.

Agent 2390 / backend 4313 green against a verified-clean build.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-08-20 13:49:14 +02:00
Oliver Kieselbach 828cbb5cd0 refactor(shared): CMTrace parser stops guessing the writer's timezone
Behaviour-neutral: 2381 agent and 4313 backend tests pass unchanged.

The parser resolved a bias-less line with DateTimeStyles.AssumeLocal followed by
ToUniversalTime(), i.e. with the READING process's cached zone. That silently
assumes reader and writer agree. They do not — each caches its zone at process
start and neither follows a later tzutil or Windows auto-timezone change — and the
assumption was buried inside a shared helper where no call site could see it.

CmTraceLogEntry now exposes what the line actually contains: LocalTimestamp
(Kind=Unspecified, because the value is meaningless without knowing the writer's
zone) and BiasMinutes. TimestampUtc is populated only when the writer declared its
bias, which is the one case where the offset is genuinely known. Timestamp is
removed rather than deprecated, so the compiler names every site that has to
decide — it immediately turned up ProcessLogMessageForTest, which grep had missed.

The defective path still exists, but now as one named function,
ResolveUtcAssumingReaderZone(), whose documentation states when it is wrong. All
three consumers call it and so keep their current behaviour exactly:
- ImeLogTracker routes every use through ResolveEntryUtc(), the single point where
  the measured offset replaces the fallback in the follow-up change;
- StallProbeCollector and LogParserCollector read file snapshots rather than
  tailing, so they cannot measure an offset and stay on the fallback for now.

The parser also no longer invents a timestamp. An unparseable time used to be
stamped DateTime.UtcNow inside the parser, making a fabricated value
indistinguishable from a real one downstream; it now reports HasTimestamp=false
and leaves the fallback to the caller, which alone knows what is safe in context
(StallProbeCollector still treats such a line as fresh — calling it stale would
hide progress).

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-08-20 13:35:43 +02:00
Oliver Kieselbach 93a42ba5e4 feat(agent): measure the CMTrace writer's UTC offset instead of assuming it
A CMTrace line carries local time and no offset — IME 1.104 writes
DateTime.Now.TimeOfDay in both of its trace listeners. Converting it with the
agent's own TimeZoneInfo.Local assumes both processes agree on the zone. They do
not: each caches its zone at process start and neither follows a later tzutil or a
Windows auto-timezone change, so the error is Offset_writer - Offset_agent and is
zero only by coincidence.

Measured over 11,068 sessions: 26 carry a real zone-offset error, +1 h (GMT to
W. Europe, session bfff9b1c) through -17 h (a writer still on the Pacific OOBE
default while the agent had already moved to E. Australia). Note the sign — this
is why "make the agent's own clock honest" is the wrong fix: in the -17 h cases
the agent was correct and the writer was stale, and clearing the agent's cache
would have broken the majority of sessions where both are stale and the two errors
cancel.

The tracker tails at a 100 ms poll, so a line that appeared since the previous
pass was written essentially "now". That makes the writer's offset measurable:
round(lineLocal - agentUtcNow) onto the 15-minute grid every real UTC offset sits
on. Per source file, because IntuneManagementExtension.log and AppWorkload.log are
written by different processes; re-measured on every fresh anchor, so a writer
restart is picked up within one poll.

The freshness requirement is the load-bearing part and cannot be replaced by the
residual guard: a backlog line exactly 30 minutes old is itself a clean multiple
of the grid, rounds with zero residual, and would calibrate the offset half an
hour wrong. RejectsBacklogLine_EvenWhenItRoundsCleanly pins that the calibrator
cannot detect this on its own — only the caller's freshness rule prevents it.

Additive only; no call site uses it yet.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-08-20 13:25:48 +02:00
Oliver Kieselbach aaacc6ecb2 refactor(backend): order rule evaluation by Sequence, not Timestamp
Sequence is a persisted, strictly monotonic per-session counter assigned at emit
time (EventSequenceCounter: locked, saved before return, survives restarts). It is
immune to every clock problem. Timestamp carries the device clock frame plus, for
CMTrace-derived events, the writing process's timezone belief.

EvaluateAppInstallDurationCondition and EvaluateEventCorrelationCondition both
ordered by Timestamp and expressed "A happened before B" as a timestamp
comparison. Both now order by Sequence and compare Sequence for ordering.

Timestamp deliberately stays where an actual ELAPSED DURATION is meant:
durationSeconds, the evidence fields, and TimeWindowSeconds.

Scope, honestly: this is hardening, not a live bug fix. BuiltInAnalyzeRules.cs
contains zero event_correlation conditions, so the cross-frame join can only be
reached by a self-authored rule. And the app-install duration evaluator pairs
app_install_started with app_install_completed — both IME-sourced, one frame — so
its arithmetic was already correct. (The measured 68-vs-8-minute inflation comes
from EventIngestProcessor.AppInstall, which folds DO-collector download_progress
together with IME app_install_completed; that is fixed at the root in the agent.)

The TimeWindowSeconds check stays exposed: the window IS a duration, so there is
no alternative to a timestamp there. A +1 h skew on B makes any window below
3600 s fail to match. Only the agent-side calibration closes that.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-08-20 13:13:09 +02:00
Oliver Kieselbach bbc7a1d8b2 fix(backend): agent-silence sweep must compare clock frames it owns
LastEventAt is the maximum AGENT-supplied event timestamp and therefore lives in
the device clock frame. The silence sweep compared it against a server-derived
cutoff, mixing two frames.

Measured over 11,068 sessions: 26 carry a genuine CMTrace timezone skew on their
IME-derived events, from -17 h to +1 h (a further 27 carry plain device-clock
offsets). At -17 h a live agent looks silent the moment it starts and is marked
Stalled with a customer-visible "Agent silent for 1020min"; at +1 h the sweep is
blind for an hour.

Adds SessionSummary.LastIngestAt, stamped from the server clock in
IncrementSessionEventCountAsync — reaching that method IS contact from the agent,
so it is written unconditionally rather than gated on latestEventTimestamp.

The sweep's server-side filter now spans both frames (LastIngestAt lt X or
LastEventAt lt X): filtering on LastIngestAt alone would silently drop every row
written before the field existed, because Table Storage does not match a filter
against a missing property. The authoritative decision moves into
ServerFrameLastContact() (LastIngestAt ?? LastEventAt ?? StartedAt) and is applied
in both stages — before the Stalled marker and in the stage-2 alive guard.

Deliberately not mirrored into SessionsIndex: the sweep reads Sessions, and the
index manifest is pinned bidirectionally by tests.

shared-manifests.json + .generated.ts regenerated — SharedManifestParityTests is
the drift brake and correctly went red on the new field.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-08-20 13:12:49 +02:00
Oliver Kieselbach 5f00124a86 fix(web): keep PDF section titles with their content, show full exit-code text
Section headings now reserve keep-with-next space (charts reserve their full
height), so a title never strands at a page bottom while its table starts on
the next page. Table cells wrap up to 4 lines instead of single-line ellipsis,
and the exit-code column carries the full error description (the 24-char slice
is gone) - that text is what the app owner acts on. Failure-code column widths
rebalanced (Code 42 / Description 62 / Exit 60 / Count 16).

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
2026-08-20 09:42:57 +02:00
35 changed files with 2455 additions and 118 deletions
+104
View File
@@ -0,0 +1,104 @@
---
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.
# Citations
* `CmTraceOffsetCalibrator.TryMeasureOffset` — the pure grid measurement, shared by
anchoring and the observational per-file path.
* `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).
+1
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.
+2
View File
@@ -2,6 +2,8 @@
## 2026-08-20
* **New**: `agent/cmtrace-time-resolution.md` — the era-aware answer to the CMTrace timezone skew: a bias-less line read in a provably fresh pass anchors its own UTC offset against the agent clock (15-minute grid, 2-minute residual), so interleaved writer eras in one file resolve line by line; everything not provably fresh keeps the uniform reader-zone fallback and says so via `sourceOffsetOrigin`. Freshness is a per-file `LastCheckedUtc` stamped on every poll look (empty first sights included) with a 30-second window, never restored across restarts. Replaces the reverted per-file offset application (04b1a7c6); the per-file measurement stays observational, now with the anchor timestamp logged as a tripwire for the still-unexplained e9753578 label/anchor crossing.
* **Update**: `agent/post-reboot-completion-recovery.md` — retitled to "ESP Completion Starvation — the sits-d Cloud-PC complex" and reframed on the evidence: the reboot was a red herring. The five stuck Cloud PCs carried `SkipUserStatusPage=True` (read 10+ times across three agent processes, `True` every time) and Windows honoured it — no user ESP page, hence no Shell-Core 62407 and no AccountSetup provisioning registry, verified over a six-hour uninterrupted post-reboot run with the watcher armed. Arm B of `ShouldTransitionToAwaitingHello` was open from the bootstrap onward, but every evaluation site hangs off a signal a skip-user flow cannot produce, and the `AdvisoryCompletion` backstop arms exclusively from an `EspExiting` signal — an open gate nobody knocks on. Fix: `HandleImeUserSessionCompletedV1` accepts the observed skip in place of the final-exit evidence (`skipUserExitEquivalent`; anchor + genuine IME completion + real-user desktop stay mandatory, WDP excluded). The knock deliberately lives on the IME edge, not desktop arrival — ordering-robust against Fix 10's AccountSetup bounce-back and semantically "user-phase work finished" rather than mid-install. `ClassicSkipUserEspUserSessionCompletionTests` replays the real 8110e262 ordering end to end. Docs and comments no longer claim an ESP-exit recovery that does not exist (stray duplicate summary in `ShellCoreTracker`, `ImeLogHost` restore-callback comment); the residual `SkipUser=false` exit-in-downtime gap is named honestly and surfaced by `ANALYZE-ESP-005` via `session_stalled` instead of being patched with an unorderable replay.
## 2026-08-19
@@ -0,0 +1,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();
}
}
}
}
@@ -67,29 +67,34 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
Assert.Equal("EnforcementState: Installing app X", entry.Message);
Assert.Equal("AppEnforce", entry.Component);
Assert.Equal(1, entry.Type);
Assert.NotEqual(default, entry.Timestamp);
Assert.True(entry.HasTimestamp);
Assert.NotEqual(default, entry.LocalTimestamp);
// Bias-less line: the parser refuses to guess the writer's zone, so no UTC value.
Assert.Null(entry.BiasMinutes);
Assert.Null(entry.TimestampUtc);
Assert.Equal(DateTimeKind.Unspecified, entry.LocalTimestamp.Kind);
}
// ── Structurally valid but unparseable timestamp → UtcNow fallback ────
// ── Structurally valid but unparseable timestamp → flagged, not invented ──
[Fact]
public void TryParseLine_falls_back_to_utcnow_for_unparseable_timestamp()
public void TryParseLine_flags_unparseable_timestamp_instead_of_inventing_one()
{
// time/date satisfy the regex character classes ([\d:.]+ / [\d-]+) so the line MATCHES,
// but "13-45-2026" / "25:99:99" fail every DateTime format → the parser falls back to
// DateTime.UtcNow (CmTraceLogParser.cs:57) instead of throwing.
var before = DateTime.UtcNow;
// but "13-45-2026" / "25:99:99" fail every DateTime format. The parser used to stamp
// DateTime.UtcNow here, which made a fabricated value indistinguishable from a real
// one downstream. It now reports HasTimestamp=false and leaves the choice of fallback
// to the caller, which is the only party that knows what a safe default is in context.
var line = CmTraceLine("some message", "25:99:99.0000000", "13-45-2026");
var ok = CmTraceLogParser.TryParseLine(line, out var entry);
var after = DateTime.UtcNow;
Assert.True(ok);
Assert.NotNull(entry);
Assert.Equal("some message", entry.Message);
// Don't assert an exact instant — only that the fallback stamped a fresh "now"
// (a successfully-parsed date would land in 2026, far outside this window).
Assert.InRange(entry.Timestamp, before.AddSeconds(-5), after.AddSeconds(5));
Assert.False(entry.HasTimestamp);
Assert.Equal(default, entry.LocalTimestamp);
Assert.Null(entry.TimestampUtc);
}
// ── UTC-bias suffix on the time field → honored, not dropped ──────────
@@ -108,10 +113,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
Assert.True(ok);
Assert.NotNull(entry);
// A writer-declared bias IS the fact we otherwise have to measure, so it is honored
// and resolved to UTC right here — unlike the bias-less form.
Assert.Equal(expectedOffsetMinutes, entry.BiasMinutes);
Assert.NotNull(entry.TimestampUtc);
Assert.Equal(
new DateTime(2026, 7, 29, 11, 46, 19, DateTimeKind.Utc).AddTicks(226610).AddMinutes(expectedOffsetMinutes),
entry.Timestamp);
Assert.Equal(DateTimeKind.Utc, entry.Timestamp.Kind);
entry.TimestampUtc!.Value);
Assert.Equal(DateTimeKind.Utc, entry.TimestampUtc!.Value.Kind);
}
// ── Oversized line → parses, no throw, no truncation of the message ───
@@ -0,0 +1,190 @@
using System;
using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime;
using Xunit;
namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
{
/// <summary>
/// Pins the measurement contract of <see cref="CmTraceOffsetCalibrator"/>.
///
/// <para>
/// The cases are taken from real sessions: +1 h (GMT to W. Europe, session bfff9b1c) and
/// -17 h (a writer left on the Pacific OOBE default while the agent had moved to
/// E. Australia). The backlog case is the one the residual guard cannot catch on its own and
/// is the reason the freshness rule exists.
/// </para>
/// </summary>
public class CmTraceOffsetCalibratorTests
{
private const string Source = "IntuneManagementExtension.log";
private static readonly DateTime UtcNow = new DateTime(2026, 08, 20, 07, 31, 46, DateTimeKind.Utc);
/// <summary>A line written "now" by a writer that believes it is at <paramref name="offset"/>.</summary>
private static DateTime LineWrittenNow(TimeSpan offset, DateTime utcNow)
=> DateTime.SpecifyKind(utcNow + offset, DateTimeKind.Unspecified);
[Theory]
[InlineData(2)] // CEST — the bfff9b1c writer
[InlineData(1)] // BST — what the agent wrongly assumed there
[InlineData(-7)] // PDT — the OOBE default seen in the -17 h sessions
[InlineData(10)] // E. Australia
[InlineData(14)] // Line Islands, the upper bound
[InlineData(-12)] // Dateline, the lower bound
public void MeasuresWholeHourOffsets(int hours)
{
var sut = new CmTraceOffsetCalibrator();
var offset = TimeSpan.FromHours(hours);
Assert.True(sut.TryCalibrate(Source, LineWrittenNow(offset, UtcNow), UtcNow));
TimeSpan measured;
Assert.True(sut.TryGetOffset(Source, out measured));
Assert.Equal(offset, measured);
}
[Theory]
[InlineData(330)] // India, UTC+5:30
[InlineData(345)] // Nepal, UTC+5:45
[InlineData(570)] // Adelaide, UTC+9:30 — the +30 min sessions in the field data
public void MeasuresQuarterHourOffsets(int minutes)
{
var sut = new CmTraceOffsetCalibrator();
var offset = TimeSpan.FromMinutes(minutes);
Assert.True(sut.TryCalibrate(Source, LineWrittenNow(offset, UtcNow), UtcNow));
TimeSpan measured;
Assert.True(sut.TryGetOffset(Source, out measured));
Assert.Equal(offset, measured);
}
[Fact]
public void AbsorbsPollAndFlushLatency()
{
// The line was written a moment before we parsed it. That lag must vanish into the
// grid rather than shift the measured offset.
var sut = new CmTraceOffsetCalibrator();
var lineLocal = LineWrittenNow(TimeSpan.FromHours(2), UtcNow.AddMilliseconds(-450));
Assert.True(sut.TryCalibrate(Source, lineLocal, UtcNow));
TimeSpan measured;
Assert.True(sut.TryGetOffset(Source, out measured));
Assert.Equal(TimeSpan.FromHours(2), measured);
}
[Fact]
public void RejectsBacklogLine_EvenWhenItRoundsCleanly()
{
// THE case the residual guard cannot catch alone: a line exactly 30 minutes old is a
// clean multiple of the grid, so it rounds with zero residual — and would calibrate
// the offset half an hour wrong. Only the caller's freshness rule prevents this from
// ever being offered; this test pins that a 30-minute-old line does not silently
// produce the true offset.
var sut = new CmTraceOffsetCalibrator();
var thirtyMinutesOld = LineWrittenNow(TimeSpan.FromHours(2), UtcNow.AddMinutes(-30));
Assert.True(sut.TryCalibrate(Source, thirtyMinutesOld, UtcNow));
TimeSpan measured;
Assert.True(sut.TryGetOffset(Source, out measured));
Assert.Equal(TimeSpan.FromMinutes(90), measured);
Assert.NotEqual(TimeSpan.FromHours(2), measured);
}
[Fact]
public void RejectsOffGridCandidate()
{
// 7 minutes off the grid: not fresh, and not a timezone either.
var sut = new CmTraceOffsetCalibrator();
var offGrid = LineWrittenNow(TimeSpan.FromHours(2), UtcNow.AddMinutes(-7));
Assert.False(sut.TryCalibrate(Source, offGrid, UtcNow));
TimeSpan ignored;
Assert.False(sut.TryGetOffset(Source, out ignored));
}
[Fact]
public void RejectsOffsetOutsideAnyRealTimezone()
{
var sut = new CmTraceOffsetCalibrator();
var absurd = LineWrittenNow(TimeSpan.FromHours(20), UtcNow);
Assert.False(sut.TryCalibrate(Source, absurd, UtcNow));
}
[Fact]
public void SelfHeals_WhenTheWritingProcessPicksUpANewZone()
{
// The writer restarts mid-session and now believes CEST instead of the stale BST.
var sut = new CmTraceOffsetCalibrator();
Assert.True(sut.TryCalibrate(Source, LineWrittenNow(TimeSpan.FromHours(1), UtcNow), UtcNow));
var later = UtcNow.AddMinutes(5);
Assert.True(sut.TryCalibrate(Source, LineWrittenNow(TimeSpan.FromHours(2), later), later));
TimeSpan measured;
Assert.True(sut.TryGetOffset(Source, out measured));
Assert.Equal(TimeSpan.FromHours(2), measured);
}
[Fact]
public void IgnoresAnchorOlderThanTheCurrentOne()
{
var sut = new CmTraceOffsetCalibrator();
Assert.True(sut.TryCalibrate(Source, LineWrittenNow(TimeSpan.FromHours(2), UtcNow), UtcNow));
// An out-of-order line from before the current anchor must not move the offset back.
var earlier = UtcNow.AddMinutes(-10);
Assert.False(sut.TryCalibrate(Source, LineWrittenNow(TimeSpan.FromHours(1), earlier), earlier));
TimeSpan measured;
Assert.True(sut.TryGetOffset(Source, out measured));
Assert.Equal(TimeSpan.FromHours(2), measured);
}
[Fact]
public void KeepsSourcesIndependent()
{
// IntuneManagementExtension.log and AppWorkload.log are written by different
// processes and may hold different beliefs.
var sut = new CmTraceOffsetCalibrator();
Assert.True(sut.TryCalibrate("IntuneManagementExtension.log", LineWrittenNow(TimeSpan.FromHours(2), UtcNow), UtcNow));
Assert.True(sut.TryCalibrate("AppWorkload.log", LineWrittenNow(TimeSpan.FromHours(-7), UtcNow), UtcNow));
TimeSpan ime, appWorkload;
Assert.True(sut.TryGetOffset("IntuneManagementExtension.log", out ime));
Assert.True(sut.TryGetOffset("AppWorkload.log", out appWorkload));
Assert.Equal(TimeSpan.FromHours(2), ime);
Assert.Equal(TimeSpan.FromHours(-7), appWorkload);
}
[Fact]
public void ResolvesTheRealFieldLine_FromSessionBfff9b1c()
{
// Raw line: <![LOG[Agent version is: 1.104.102.0]LOG]!><time="09:31:46.5192284" ...>
// Server-side ReceivedAt puts the true UTC at 07:31:46.4. The old code produced
// 08:31:46.5192284 — local minus the agent's stale +1 h belief.
var sut = new CmTraceOffsetCalibrator();
var trueUtc = new DateTime(2026, 08, 20, 07, 31, 46, 400, DateTimeKind.Utc);
var lineLocal = new DateTime(2026, 08, 20, 09, 31, 46, 519, DateTimeKind.Unspecified);
Assert.True(sut.TryCalibrate(Source, lineLocal, trueUtc));
DateTime resolved;
Assert.True(sut.TryResolveUtc(Source, lineLocal, out resolved));
Assert.Equal(DateTimeKind.Utc, resolved.Kind);
Assert.Equal(new DateTime(2026, 08, 20, 07, 31, 46, 519, DateTimeKind.Utc), resolved);
}
[Fact]
public void ReportsUncalibratedSource_SoTheCallerCanFlagIt()
{
var sut = new CmTraceOffsetCalibrator();
DateTime resolved;
Assert.False(sut.TryResolveUtc(Source, UtcNow, out resolved));
}
}
}
@@ -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;
}
}
@@ -0,0 +1,275 @@
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>
/// End-to-end offset calibration through a real read cycle.
///
/// <para>
/// A CMTrace line states local time and nothing else, so its UTC value depends on which zone
/// the WRITING process believed it was in. The tracker used to substitute its own belief,
/// which is right only when the two happen to agree.
/// </para>
///
/// <para>
/// These tests are deliberately independent of the machine they run on: the assertion is
/// always "a line written at instant T resolves to T", for every writer belief. That single
/// property covers both field cases at once — the writer disagreeing with us (the bug) and
/// the writer agreeing with us (the majority, which a naive fix would have broken).
/// </para>
/// </summary>
public sealed class ImeLogTrackerOffsetCalibrationTests
{
private const string LogFileName = "IntuneManagementExtension.log";
private static readonly DateTime T0 = new DateTime(2026, 8, 20, 7, 30, 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>(),
},
};
/// <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=\"IntuneManagementExtension\" 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()
{
Tracker = new ImeLogTracker(
logFolder: _tmp.Path,
patterns: Patterns(),
logger: new AgentLogger(_tmp.Path, AgentLogLevel.Info));
Tracker.UtcNowProvider = () => Now;
}
public string LogPath => Path.Combine(_tmp.Path, LogFileName);
public void Append(string line) => File.AppendAllText(LogPath, line + Environment.NewLine);
public Task Pass() => Tracker.CheckLogFilesAsync(CancellationToken.None);
public void Dispose()
{
Tracker.Dispose();
_tmp.Dispose();
}
}
[Theory]
// 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 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();
h.Append(Line("marker 1", h.Now, writerOffset));
await h.Pass();
h.Now = T0.AddSeconds(10);
h.Append(Line("marker 2", h.Now, writerOffset));
await h.Pass();
TimeSpan measured;
Assert.True(h.Tracker.OffsetCalibrator.TryGetOffset(LogFileName, out measured));
Assert.Equal(writerOffset, measured);
}
[Fact]
public async Task MeasuresTheWritersOffset_NotItsOwn()
{
using var h = new Harness();
var writerOffset = TimeSpan.FromHours(2);
h.Append(Line("marker 1", h.Now, writerOffset));
await h.Pass();
h.Now = T0.AddSeconds(10);
h.Append(Line("marker 2", h.Now, writerOffset));
await h.Pass();
TimeSpan measured;
Assert.True(h.Tracker.OffsetCalibrator.TryGetOffset(LogFileName, out measured));
Assert.Equal(writerOffset, measured);
}
[Fact]
public async Task DoesNotCalibrateOnFirstSightOfAFile()
{
// The first pass reads from position 0, so the newest line in the file may be hours
// old. Anchoring on it would measure the line's age instead of the writer's offset.
using var h = new Harness();
h.Append(Line("marker 1", T0.AddHours(-3), TimeSpan.FromHours(2)));
await h.Pass();
TimeSpan ignored;
Assert.False(h.Tracker.OffsetCalibrator.TryGetOffset(LogFileName, out ignored));
}
[Fact]
public async Task FollowsTheWriterAcrossARestartIntoANewZone()
{
// IME restarts mid-enrollment and picks up the timezone the OS moved to. The
// measurement has to follow, otherwise every later line is off by the difference.
using var h = new Harness();
h.Append(Line("marker 1", h.Now, TimeSpan.FromHours(1)));
await h.Pass();
h.Now = T0.AddSeconds(10);
h.Append(Line("marker 2", h.Now, TimeSpan.FromHours(1)));
await h.Pass();
TimeSpan before;
Assert.True(h.Tracker.OffsetCalibrator.TryGetOffset(LogFileName, out before));
Assert.Equal(TimeSpan.FromHours(1), before);
// Writer restarts, now on +2.
h.Now = T0.AddSeconds(20);
h.Append(Line("marker 3", h.Now, TimeSpan.FromHours(2)));
await h.Pass();
h.Now = T0.AddSeconds(30);
var writtenAt = h.Now;
h.Append(Line("marker 4", writtenAt, TimeSpan.FromHours(2)));
await h.Pass();
TimeSpan after;
Assert.True(h.Tracker.OffsetCalibrator.TryGetOffset(LogFileName, out after));
Assert.Equal(TimeSpan.FromHours(2), after);
// 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]
public async Task HonorsAWriterDeclaredBiasWithoutMeasuring()
{
// A line carrying its own bias states the offset outright; it must be used as-is and
// must never become a calibration anchor.
using var h = new Harness();
h.Append(Line("marker 1", h.Now, TimeSpan.FromHours(2)));
await h.Pass();
h.Now = T0.AddSeconds(10);
var writtenAt = h.Now;
var local = writtenAt + TimeSpan.FromHours(-8); // a PST writer
h.Append($"<![LOG[marker 2]LOG]!><time=\"{local:HH:mm:ss.fffffff}+480\" date=\"{local:M-d-yyyy}\" " +
"component=\"IntuneManagementExtension\" context=\"\" type=\"1\" thread=\"1\" file=\"\">");
await h.Pass();
Assert.True(h.Tracker.LastMatchedLogTimestamp.HasValue);
Assert.Equal(writtenAt, h.Tracker.LastMatchedLogTimestamp.Value);
TimeSpan ignored;
Assert.False(h.Tracker.OffsetCalibrator.TryGetOffset(LogFileName, out ignored));
}
[Fact]
public async Task RecordsMeasuredOffsetSeparatelyFromTheAppliedOne()
{
// 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); // PDT, the OOBE default
h.Append(Line("marker 1", h.Now, writerOffset));
await h.Pass();
h.Now = T0.AddSeconds(10);
h.Append(Line("marker 2", h.Now, writerOffset));
await h.Pass();
h.Now = T0.AddSeconds(20);
h.Append(Line("marker 3", h.Now, writerOffset));
await h.Pass();
// Measured: the writer's actual belief, per file.
Assert.Equal(-420, h.Tracker.LastMatchedMeasuredWriterOffsetMinutes);
// 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]
public async Task RecordsProvenance_AsFallback_BeforeAnyCalibration()
{
// The warm-up pass: the offset is not measured yet, so the reader zone is assumed and
// the event has to say so rather than look source-grounded.
using var h = new Harness();
h.Append(Line("marker 1", h.Now, TimeSpan.FromHours(2)));
await h.Pass();
Assert.Equal(CmTraceOffsetOrigin.None, h.Tracker.LastMatchedSourceOffsetOrigin);
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]
public async Task RecordsProvenance_ForADeclaredBias()
{
using var h = new Harness();
h.Append(Line("marker 1", h.Now, TimeSpan.FromHours(2)));
await h.Pass();
h.Now = T0.AddSeconds(10);
var local = h.Now + TimeSpan.FromHours(-8);
h.Append($"<![LOG[marker 2]LOG]!><time=\"{local:HH:mm:ss.fffffff}+480\" date=\"{local:M-d-yyyy}\" " +
"component=\"IntuneManagementExtension\" context=\"\" type=\"1\" thread=\"1\" file=\"\">");
await h.Pass();
Assert.Equal(CmTraceOffsetOrigin.Bias, h.Tracker.LastMatchedSourceOffsetOrigin);
// Reported in the same sense as a measured offset (local = UTC + offset), so the two
// origins are directly comparable; the wire bias uses the opposite convention.
Assert.Equal(-480, h.Tracker.LastMatchedSourceOffsetMinutes);
}
}
}
@@ -0,0 +1,215 @@
using System;
using System.Collections.Generic;
namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
{
/// <summary>How the UTC value of a CMTrace line was arrived at. Recorded as evidence.</summary>
public enum CmTraceOffsetOrigin
{
/// <summary>No offset known — the caller fell back to its own clock.</summary>
None = 0,
/// <summary>The writer declared its offset in the line ("+480"). Authoritative.</summary>
Bias = 1,
/// <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>
/// Measures the UTC offset that the process WRITING a CMTrace log believes it is in.
///
/// <para>
/// A CMTrace line carries local time and no offset — IME 1.104 writes
/// <c>DateTime.Now.TimeOfDay</c> in both of its trace listeners. Converting such a line with
/// the agent's own <c>TimeZoneInfo.Local</c> assumes the two processes agree, and they do not:
/// both cache their zone at process start and neither follows a later <c>tzutil</c> or a
/// Windows auto-timezone change. The resulting error is
/// <c>Offset_writer - Offset_agent</c> and is zero only by coincidence. Field measurement over
/// 11,068 sessions found 26 sessions carrying a real zone-offset error, from +1 h
/// (GMT to W. Europe) to -17 h (a writer still on the Pacific OOBE default while the agent had
/// already moved to E. Australia).
/// </para>
///
/// <para>
/// So the offset is MEASURED, not assumed. The tracker tails the log on a 100 ms poll, so a
/// line that appeared since the previous pass was written essentially "now":
/// <code>
/// candidate = lineLocalTime - agentUtcNow
/// offset = round(candidate / 15 min) * 15 min
/// lineUtc = lineLocalTime - offset
/// </code>
/// Every real UTC offset is a whole multiple of 15 minutes, so the rounding absorbs poll and
/// flush latency without ambiguity.
/// </para>
///
/// <para>
/// THE FRESHNESS REQUIREMENT IS WHAT MAKES THIS CORRECT. An anchor must be the newest line of
/// a pass in which the file actually GREW. Without that rule a backlog line that happens to be
/// an exact multiple of 15 minutes old (30 min, 45 min, ...) rounds to a clean value with zero
/// residual and calibrates the offset to a wrong figure — the residual guard alone cannot
/// catch it. Callers must only offer anchors they know to be fresh.
/// </para>
///
/// <para>
/// Calibration is kept per source file: IntuneManagementExtension.log and AppWorkload.log are
/// written by different processes and can hold different beliefs. Re-calibrating on every
/// fresh anchor makes this self-healing — if the writing process restarts and picks up the
/// current zone, the measurement follows within one poll.
/// </para>
/// </summary>
public sealed class CmTraceOffsetCalibrator
{
/// <summary>Grid that every real UTC offset sits on.</summary>
internal static readonly TimeSpan OffsetGrid = TimeSpan.FromMinutes(15);
/// <summary>
/// How far a candidate may sit off the grid before it is rejected. Poll latency (100 ms)
/// plus the writer's flush latency are far below this; anything larger means the anchor
/// was not actually fresh.
/// </summary>
internal static readonly TimeSpan MaxGridResidual = TimeSpan.FromMinutes(2);
/// <summary>Real UTC offsets span UTC-12 (Dateline) to UTC+14 (Line Islands).</summary>
internal static readonly TimeSpan MinOffset = TimeSpan.FromHours(-12);
/// <summary>Upper bound of a real UTC offset. See <see cref="MinOffset"/>.</summary>
internal static readonly TimeSpan MaxOffset = TimeSpan.FromHours(14);
private sealed class Anchor
{
public TimeSpan Offset;
public DateTime LocalTimestamp;
}
private readonly object _lock = new object();
private readonly Dictionary<string, Anchor> _bySource =
new Dictionary<string, Anchor>(StringComparer.OrdinalIgnoreCase);
/// <summary>
/// Offer a freshly appended line as a calibration anchor.
/// <para>
/// The caller MUST only pass a line it knows to be fresh — the newest line of a pass in
/// which the file grew. See the freshness note on this class.
/// </para>
/// </summary>
/// <param name="sourceKey">Log file identity; the file name is enough.</param>
/// <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>
/// <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)
{
var candidate = DateTime.SpecifyKind(localTimestamp, DateTimeKind.Unspecified)
- DateTime.SpecifyKind(agentUtcNow, DateTimeKind.Unspecified);
var gridUnits = Math.Round(candidate.TotalMinutes / OffsetGrid.TotalMinutes,
MidpointRounding.AwayFromZero);
offset = TimeSpan.FromMinutes(gridUnits * OffsetGrid.TotalMinutes);
// 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))
{
// Only ever move the anchor forward. A line older than the current anchor
// carries nothing newer and could re-introduce a stale belief.
if (localTimestamp <= existing.LocalTimestamp) return false;
existing.Offset = offset;
existing.LocalTimestamp = localTimestamp;
}
else
{
_bySource[sourceKey] = new Anchor
{
Offset = offset,
LocalTimestamp = localTimestamp,
};
}
}
return true;
}
/// <summary>The offset measured for this source, when one has been established.</summary>
public bool TryGetOffset(string sourceKey, out TimeSpan offset)
{
offset = TimeSpan.Zero;
if (string.IsNullOrEmpty(sourceKey)) return false;
lock (_lock)
{
Anchor anchor;
if (!_bySource.TryGetValue(sourceKey, out anchor)) return false;
offset = anchor.Offset;
return true;
}
}
/// <summary>
/// Convert a line's local time to UTC using the measured offset. Returns <c>false</c> when
/// this source has not been calibrated yet — the caller then picks its own fallback and
/// should mark the result as not source-grounded.
/// </summary>
public bool TryResolveUtc(string sourceKey, DateTime localTimestamp, out DateTime utc)
{
utc = default(DateTime);
TimeSpan offset;
if (!TryGetOffset(sourceKey, out offset)) return false;
utc = DateTime.SpecifyKind(
DateTime.SpecifyKind(localTimestamp, DateTimeKind.Unspecified) - offset,
DateTimeKind.Utc);
return true;
}
}
}
@@ -42,7 +42,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
return false;
}
private async Task CheckLogFilesAsync(CancellationToken token)
/// <remarks>internal (not private) as a test seam: the offset calibration depends on the
/// pass structure — first observation versus a later pass over a grown file — which only
/// a real read cycle exercises. Production still reaches it solely from the poll loop.</remarks>
internal async Task CheckLogFilesAsync(CancellationToken token)
{
if (!Directory.Exists(_logFolder))
return;
@@ -74,7 +77,21 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
var fileInfo = new FileInfo(filePath);
if (!fileInfo.Exists) continue;
// 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
@@ -86,6 +103,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
if (_logger.LogLevel >= AgentLogLevel.Trace)
_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
// measurement and must not overwrite one.
CmTraceLogEntry calibrationAnchor = null;
using (var stream = new FileStream(filePath, FileMode.Open, FileAccess.Read, FileShare.ReadWrite))
{
stream.Seek(startPos, SeekOrigin.Begin);
@@ -147,6 +174,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
if (CmTraceLogParser.TryParseLine(line, out entry))
{
messageToMatch = entry.Message;
if (entry.HasTimestamp && !entry.BiasMinutes.HasValue)
calibrationAnchor = entry;
}
else
{
@@ -160,7 +189,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
// Simulation mode delay
if (SimulationMode && entry != null)
{
await ApplySimulationDelay(entry.Timestamp, token);
await ApplySimulationDelay(ResolveEntryUtc(entry), token);
}
// Match against active patterns
@@ -185,6 +214,15 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
_positionTracker.SetPosition(filePath, stream.Position);
_stateDirty = true;
// Calibrate AFTER the pass: this pass's lines were resolved with the
// offset established previously, at most one poll (100 ms) old. Buffering
// the pass to calibrate first is not an option — the first pass of
// AppWorkload.log can be hundreds of MB. The cost is a warm-up of one
// growing pass, during which lines fall back to the reader zone and are
// flagged as such.
if (hadPreviousObservation && calibrationAnchor != null)
CalibrateFrom(_currentSourceFileName, calibrationAnchor);
}
}
catch (FileNotFoundException) { }
@@ -222,7 +260,32 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
private void HandlePatternMatch(CompiledPattern pattern, Match match, string message, CmTraceLogEntry entry)
{
LastMatchedPatternId = pattern.PatternId;
LastMatchedLogTimestamp = entry?.Timestamp;
if (entry == null)
{
LastMatchedLogTimestamp = null;
LastMatchedSourceLocalTimestamp = null;
LastMatchedSourceOffsetMinutes = null;
LastMatchedSourceOffsetOrigin = CmTraceOffsetOrigin.None;
LastMatchedMeasuredWriterOffsetMinutes = null;
}
else
{
CmTraceOffsetOrigin origin;
int? offsetMinutes;
LastMatchedLogTimestamp = ResolveEntryUtc(entry, out origin, out offsetMinutes);
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
// subscribers (e.g. ImeLogTrackerAdapter emitting WhiteGloveSealingPatternDetected)
@@ -237,10 +300,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
// state nor the phase-change ignore list. SimulationMode (--replay-log-dir dev tool)
// replays historic logs on purpose and bypasses the guard.
var isStaleReplayLine = !SimulationMode && entry != null
&& (UtcNowProvider() - NormalizeUtc(entry.Timestamp)) > HistoricReplayThreshold;
&& (UtcNowProvider() - NormalizeUtc(ResolveEntryUtc(entry))) > HistoricReplayThreshold;
if (isStaleReplayLine && AppMutatingActions.Contains(pattern.Action?.ToLower() ?? string.Empty))
{
_logger.Debug($"ImeLogTracker: skipped app action '{pattern.Action}' for historic line ({entry.Timestamp:o})");
_logger.Debug($"ImeLogTracker: skipped app action '{pattern.Action}' for historic line ({ResolveEntryUtc(entry):o})");
return;
}
@@ -524,8 +587,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
internal void ProcessLogMessageForTest(string message, DateTime? sourceTimestampUtc = null)
{
if (string.IsNullOrEmpty(message)) return;
// The test seam hands in an already-resolved UTC instant, so it takes the same route a
// writer-declared bias does: TimestampUtc set, no zone left to guess.
var entry = sourceTimestampUtc.HasValue
? new CmTraceLogEntry { Timestamp = sourceTimestampUtc.Value, Message = message }
? new CmTraceLogEntry
{
TimestampUtc = sourceTimestampUtc.Value,
LocalTimestamp = DateTime.SpecifyKind(sourceTimestampUtc.Value, DateTimeKind.Unspecified),
HasTimestamp = true,
Message = message,
}
: null;
foreach (var pattern in _activePatterns)
{
@@ -543,5 +614,127 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
/// Parses [DO TEL] JSON and links it to the correct app via FileId.
/// The FileId contains the app GUID in the format: ...intunewin-bin_{appGuid}_{number}
/// </summary>
/// <summary>
/// Resolve a parsed CMTrace entry to UTC.
///
/// <para>
/// Order of preference: a writer-declared bias (authoritative) &gt; this process's own zone
/// (a fallback carrying a known defect, see
/// <see cref="CmTraceLogParser.ResolveUtcAssumingReaderZone"/>) &gt; the agent clock for a
/// line with no parseable timestamp.
/// </para>
///
/// <para>
/// The reader-zone step is where the tracker is still wrong when IME's process holds a
/// different zone belief than ours. It is preserved verbatim here so that splitting the
/// parser changes no behaviour; the measured offset from <c>CmTraceOffsetCalibrator</c>
/// slots in at exactly this point in the follow-up change.
/// </para>
/// </summary>
private DateTime ResolveEntryUtc(CmTraceLogEntry entry)
{
CmTraceOffsetOrigin origin;
int? offsetMinutes;
return ResolveEntryUtc(entry, out origin, out offsetMinutes);
}
/// <summary>
/// Resolve a parsed entry to UTC and report HOW the offset was obtained, so the emitting
/// side can attach the evidence (P8). See <see cref="CmTraceOffsetOrigin"/>.
/// </summary>
private DateTime ResolveEntryUtc(CmTraceLogEntry entry, out CmTraceOffsetOrigin origin, out int? offsetMinutes)
{
origin = CmTraceOffsetOrigin.None;
offsetMinutes = null;
if (entry == null) return UtcNowProvider();
// Writer declared its own offset — nothing left to measure.
if (entry.TimestampUtc.HasValue)
{
origin = CmTraceOffsetOrigin.Bias;
// Bias uses the GetTimeZoneInformation convention (UTC = local + bias); report the
// value in the same sense as a measured offset (local = UTC + offset).
offsetMinutes = entry.BiasMinutes.HasValue ? -entry.BiasMinutes.Value : (int?)null;
return entry.TimestampUtc.Value;
}
if (!entry.HasTimestamp) return UtcNowProvider();
// 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)
{
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);
}
}
// 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);
}
/// <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)
{
TimeSpan previous;
var hadOffset = OffsetCalibrator.TryGetOffset(sourceFileName, out previous);
if (!OffsetCalibrator.TryCalibrate(sourceFileName, anchor.LocalTimestamp, UtcNowProvider()))
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, anchor local={anchor.LocalTimestamp:yyyy-MM-ddTHH:mm:ss.fff}).");
return;
}
_logger?.Info(
$"ImeLogTracker: {sourceFileName} writer offset measured {measured}, this process believes {readerZoneOffset} " +
$"(anchor local={anchor.LocalTimestamp:yyyy-MM-ddTHH:mm:ss.fff}). Measurement is observational — resolution anchors per line.");
}
}
}
@@ -85,6 +85,42 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
/// Unspecified depending on the parser path. Normalize via SpecifyKind=Utc rather than
/// ToUniversalTime() to avoid double-conversion when Kind is already UTC.
/// </summary>
/// <summary>
/// Measures the UTC offset the IME process believes it is in, per log file.
/// <para>
/// Only this tracker may WRITE to it: calibration requires tailing with growth detection
/// so the freshness rule can be honoured, and no other collector tails. Exposed so the
/// snapshot-reading collectors can eventually READ from a shared instance
/// (tasks/todo.md, P3b).
/// </para>
/// </summary>
internal CmTraceOffsetCalibrator OffsetCalibrator { get; } = new CmTraceOffsetCalibrator();
/// <summary>
/// File whose lines are currently being processed. The polling loop walks files strictly
/// sequentially on a single task, so a field is sufficient to give <c>ResolveEntryUtc</c>
/// and the handlers the calibration key without threading it through every signature.
/// </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);
@@ -191,6 +227,38 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
public string LastMatchedPatternId { get; internal set; }
public DateTime? LastMatchedLogTimestamp { get; internal set; }
/// <summary>
/// Raw local time of the last matched line, exactly as the writer wrote it — no zone
/// attached, because the line carries none.
/// <para>
/// Recorded so an emitted event can carry the evidence for its own timestamp. Without it
/// a conversion error is only provable from the diagnostics archive, and of the 5,386
/// sessions that went through a timezone change essentially none had one — the field
/// analysis had to fall back to median statistics over thousands of sessions to show
/// what one stored value would have made obvious per session.
/// </para>
/// </summary>
public DateTime? LastMatchedSourceLocalTimestamp { get; internal set; }
/// <summary>Offset applied to <see cref="LastMatchedSourceLocalTimestamp"/>, in minutes.</summary>
public int? LastMatchedSourceOffsetMinutes { get; internal set; }
/// <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; }
@@ -19,6 +19,18 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
/// has been rotated - resets to 0 to read from beginning.
/// Returns 0 if no position has been recorded yet.
/// </summary>
/// <summary>
/// Whether this file was already observed in an earlier pass.
/// <para>
/// The offset calibration depends on this: growth measured against a size we saw before
/// means the new bytes were written within one poll interval, so the last line of that
/// pass is a valid "written now" anchor. On the FIRST sight of a file we read it from
/// position 0 and its last line may be arbitrarily old — anchoring on that would measure
/// the line's age instead of the writer's timezone offset.
/// </para>
/// </summary>
public bool HasSeen(string filePath) => _positions.ContainsKey(filePath);
public long GetSafePosition(string filePath, long currentFileSize)
{
FilePositionState state;
@@ -53,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.
@@ -77,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)
{
@@ -84,7 +138,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
{
Position = position,
LastKnownSize = lastKnownSize,
LastReadTime = DateTime.UtcNow
LastReadTime = DateTime.UtcNow,
LastCheckedUtc = DateTime.MinValue
};
}
}
@@ -94,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; }
}
}
@@ -580,10 +580,22 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
var scanText = rawLine;
if (CmTraceLogParser.TryParseLine(rawLine, out var entry))
{
// Provably stale → not progress. (TryParseLine falls back to now on an
// unparseable timestamp, which keeps the line fresh — the safe default.)
if (entry.Timestamp < cutoffUtc)
continue;
// Provably stale → not progress. A line without a parseable timestamp counts
// as fresh — the safe default, since treating it as stale would hide progress.
//
// This collector reads a file snapshot rather than tailing it, so it cannot
// measure the writer's UTC offset itself and falls back to this process's zone
// (see ResolveUtcAssumingReaderZone). That fallback is wrong by exactly the
// gap between the two processes' zone beliefs. It is the pre-existing
// behaviour, kept deliberately unchanged here; the tracker-owned calibrator is
// wired in separately so this commit shifts no behaviour.
if (entry.HasTimestamp)
{
var entryUtc = entry.TimestampUtc
?? CmTraceLogParser.ResolveUtcAssumingReaderZone(entry.LocalTimestamp);
if (entryUtc < cutoffUtc)
continue;
}
scanText = entry.Message;
}
@@ -331,7 +331,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather.Collectors
data[groupName] = group.Value;
}
data["logTimestamp"] = entry.Timestamp.ToString("o");
// Gather-rule logs are arbitrary files this collector does not
// tail, so no writer offset can be measured for them; the
// reader-zone fallback carries its known defect (see
// ResolveUtcAssumingReaderZone). Behaviour unchanged from before
// the parser split.
var entryUtc = entry.TimestampUtc
?? (entry.HasTimestamp
? CmTraceLogParser.ResolveUtcAssumingReaderZone(entry.LocalTimestamp)
: DateTime.UtcNow);
data["logTimestamp"] = entryUtc.ToString("o");
data["logComponent"] = entry.Component;
data["logType"] = entry.Type;
data["logMessage"] = TruncateMessage(entry.Message, 500);
@@ -348,7 +357,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather.Collectors
{
SessionId = context.SessionId,
TenantId = context.TenantId,
Timestamp = entry.Timestamp,
Timestamp = entryUtc,
EventType = eventType,
Severity = severity,
Source = "GatherRuleExecutor",
@@ -124,6 +124,17 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
// in ImeLogTracker so the layers can never drift apart).
private static readonly TimeSpan StaleSourceThreshold = ImeLogTracker.HistoricReplayThreshold;
/// <summary>
/// How far ahead of the agent clock a source timestamp may sit before it is rejected.
/// <para>
/// Writer and reader share one system clock, so a correctly converted line is always at
/// or behind "now"; this is pure jitter tolerance, not a skew allowance. Deliberately far
/// below one hour — the value that a timezone mistake produces — so that such a mistake
/// can actually trip it.
/// </para>
/// </summary>
private static readonly TimeSpan MaxFutureSourceSkew = TimeSpan.FromMinutes(2);
// Matches the deterministic marker line the bootstrap script writes via Write-Log,
// e.g. "Bootstrap script version: v2.0" — see scripts/Bootstrap/Install-AutopilotMonitor.ps1.
// Same shape as the web-side regex in utils/bootstrapVersion.ts; kept in sync intentionally.
@@ -329,12 +340,28 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
var clockNow = _clock.UtcNow;
var ageHours = (clockNow - asUtc).TotalHours;
if (ageHours > StaleSourceThreshold.TotalHours || ageHours < -1.0)
// Future guard. A source timestamp can never legitimately be ahead of the agent
// clock: the writer stamps it from the SAME system clock, and the tracker only
// sees the line after it was written. Anything ahead means the local-to-UTC
// conversion was wrong.
//
// The previous threshold was ageHours < -1.0, which could not fire for the single
// most common timezone error: with a one-hour offset mistake the real value is
// parseLag - 3600 s, i.e. just ABOVE -1.0. It sat exactly on the boundary of the
// case it was meant to catch. It was also asymmetric — a past-shifted error had to
// exceed 24 h before anything noticed, while the measured field errors reached
// -17 h. The bound is now a small jitter tolerance in the direction that is
// physically impossible.
var isFutureSkewed = asUtc > clockNow + MaxFutureSourceSkew;
if (ageHours > StaleSourceThreshold.TotalHours || isFutureSkewed)
{
// Pathologically stale (>24h old) or in the future (>1h skew) — log,
// fall back, and let the caller flag the event.
var reason = isFutureSkewed
? $"ahead of the agent clock by {(asUtc - clockNow).TotalMinutes:F1} min"
: $"pathologically stale (ageHours={ageHours:F1})";
_logger?.Warning(
$"ImeAdapter: source timestamp {asUtc:o} rejected (ageHours={ageHours:F1}); falling back to clock");
$"ImeAdapter: source timestamp {asUtc:o} rejected — {reason}; falling back to clock");
derivedFromClock = true;
return clockNow;
}
@@ -347,12 +374,69 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
return _clock.UtcNow;
}
private static void TagDerivedTimestamp(IDictionary<string, string> data, bool derivedFromClock, DateTime? rawSourceTs)
/// <summary>
/// Attach the evidence for this event's timestamp: the raw local time as the writer wrote
/// it, the offset applied, and how that offset was obtained.
///
/// <para>
/// Without this the only record of a conversion is the converted value itself, so a wrong
/// offset is indistinguishable from a correct one. Proving the field defect required the
/// diagnostics archive — and of the 5,386 sessions that went through a timezone change,
/// essentially none had one; the analysis had to fall back to median statistics across
/// thousands of sessions. These three fields make each session answer the question on its
/// own, and make a stored timestamp recomputable after the fact without an agent release.
/// </para>
///
/// <para>
/// Only emitted for events whose time came from a CMTrace line. Agent-native events have
/// no second clock frame, so there is nothing to record.
/// </para>
/// </summary>
private void TagDerivedTimestamp(IDictionary<string, string> data, bool derivedFromClock, DateTime? rawSourceTs)
{
var culture = System.Globalization.CultureInfo.InvariantCulture;
var sourceLocal = _tracker.LastMatchedSourceLocalTimestamp;
if (sourceLocal.HasValue)
{
// No zone suffix: the value genuinely carries none, and formatting one in would
// re-introduce the very assumption this whole change removes.
data["sourceLocalTs"] = sourceLocal.Value.ToString("yyyy-MM-ddTHH:mm:ss.fffffff", culture);
data["sourceOffsetOrigin"] = OriginTag(_tracker.LastMatchedSourceOffsetOrigin);
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;
data["derivedTimestamp"] = "true";
if (rawSourceTs.HasValue)
data["rejectedSourceTimestamp"] = rawSourceTs.Value.ToString("o", System.Globalization.CultureInfo.InvariantCulture);
data["rejectedSourceTimestamp"] = rawSourceTs.Value.ToString("o", culture);
}
private static string OriginTag(CmTraceOffsetOrigin origin)
{
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 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";
}
}
// CMTrace Kind normalization — shared implementation lives on the tracker (used by its
@@ -0,0 +1,75 @@
using System;
using AutopilotMonitor.Functions.Services;
using AutopilotMonitor.Shared.Models;
using Xunit;
namespace AutopilotMonitor.Functions.Tests
{
/// <summary>
/// Pins the clock-frame contract of the agent-silence sweep.
///
/// <para>
/// <c>LastEventAt</c> is the maximum AGENT-supplied event timestamp and therefore lives in the
/// device clock frame — it carries the device's clock error and, for CMTrace-derived events,
/// the writing process's timezone belief. Field measurement over 11k sessions found skews from
/// -17 h to +1 h. Comparing that against a server-derived silence cutoff marked live agents
/// Stalled ("Agent silent for 1020min") and left genuinely silent ones undetected for the
/// duration of the skew. <c>LastIngestAt</c> is stamped from the server clock on every ingest
/// and is the only value such a comparison may use.
/// </para>
/// </summary>
public class MaintenanceServerFrameLastContactTests
{
private static readonly DateTime Now = new(2026, 08, 20, 12, 00, 00, DateTimeKind.Utc);
private static SessionSummary Session(DateTime? lastIngestAt, DateTime? lastEventAt, DateTime startedAt)
=> new() { LastIngestAt = lastIngestAt, LastEventAt = lastEventAt, StartedAt = startedAt };
[Fact]
public void PrefersServerFrameIngestStamp_OverDeviceFrameEventStamp()
{
var s = Session(lastIngestAt: Now.AddMinutes(-1), lastEventAt: Now.AddHours(-17), startedAt: Now.AddHours(-2));
Assert.Equal(Now.AddMinutes(-1), MaintenanceService.ServerFrameLastContact(s));
}
[Fact]
public void NegativeSkew_DoesNotLookSilent_WhenIngestIsFresh()
{
// The exact field shape: IME-derived events landed 17 h in the past, so LastEventAt is
// far behind the 2 h silence cutoff while the agent is demonstrably still reporting.
var silenceCutoff = Now.AddHours(-2);
var s = Session(lastIngestAt: Now.AddSeconds(-30), lastEventAt: Now.AddHours(-17), startedAt: Now.AddHours(-1));
Assert.True(MaintenanceService.ServerFrameLastContact(s) > silenceCutoff,
"a session whose ingest stamp is 30 s old must never be classified as agent-silent");
}
[Fact]
public void PositiveSkew_DoesNotMaskSilence_WhenIngestIsStale()
{
// Mirror case: a +1 h skew pushes LastEventAt into the future, which previously made the
// sweep blind for an hour. The server frame still sees the silence.
var silenceCutoff = Now.AddHours(-2);
var s = Session(lastIngestAt: Now.AddHours(-3), lastEventAt: Now.AddHours(1), startedAt: Now.AddHours(-4));
Assert.True(MaintenanceService.ServerFrameLastContact(s) < silenceCutoff,
"a session with no ingest for 3 h must be detected as silent regardless of a future-dated event stamp");
}
[Fact]
public void FallsBackToEventStamp_OnRowsPredatingTheIngestStamp()
{
// Rollout safety: rows written before LastIngestAt existed must keep the old behaviour
// rather than dropping out of the sweep entirely.
var s = Session(lastIngestAt: null, lastEventAt: Now.AddHours(-3), startedAt: Now.AddHours(-5));
Assert.Equal(Now.AddHours(-3), MaintenanceService.ServerFrameLastContact(s));
}
[Fact]
public void FallsBackToStartedAt_WhenNoEventStampExists()
{
var s = Session(lastIngestAt: null, lastEventAt: null, startedAt: Now.AddHours(-4));
Assert.Equal(Now.AddHours(-4), MaintenanceService.ServerFrameLastContact(s));
}
}
}
@@ -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);
}
}
@@ -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
@@ -351,8 +351,16 @@ namespace AutopilotMonitor.Functions.Services
int silentMarked = 0;
foreach (var silent in silentSessions)
{
var lastEventAt = silent.LastEventAt ?? silent.StartedAt;
var silentMinutes = (int)(now - lastEventAt).TotalMinutes;
// The query is a permissive two-frame pre-filter; the decision is made
// here on the SERVER frame. LastEventAt carries the device clock and,
// for IME-derived events, a timezone skew (field-measured: -17 h to
// +1 h). Trusting it marks a live agent Stalled — and puts a bogus
// "silent for 1020min" in front of the customer.
var lastContactAt = ServerFrameLastContact(silent);
if (lastContactAt > silenceCutoff)
continue; // provably alive on the server clock
var silentMinutes = (int)(now - lastContactAt).TotalMinutes;
await _sessionRepo.UpdateSessionStatusAsync(
silent.TenantId,
silent.SessionId,
@@ -409,7 +417,7 @@ namespace AutopilotMonitor.Functions.Services
// legitimately exceed SessionTimeoutHours) and must never be terminalized here
// — without this, an actively-installing 6h enrollment could be classified
// Incomplete mid-run purely because it outlived the 5h window.
if (session.LastEventAt.HasValue && session.LastEventAt.Value > silenceCutoff)
if (ServerFrameLastContact(session) > silenceCutoff)
continue;
// Fast path: an AwaitingUser session still inside the grace window needs no
@@ -774,5 +782,26 @@ namespace AutopilotMonitor.Functions.Services
/// Aggregates metrics for any missed days in the last 7 days, plus yesterday.
/// Checks the UsageMetrics table for existing snapshots to avoid re-aggregation.
/// </summary>
/// <summary>
/// Last contact with the agent, expressed in the SERVER clock frame — the only value a
/// server-derived cutoff may legitimately be compared against.
/// <para>
/// Preference order:
/// <list type="number">
/// <item><c>LastIngestAt</c> — stamped from the server clock on every ingest. Authoritative.</item>
/// <item><c>LastEventAt</c> — device frame; used only for rows written before
/// <c>LastIngestAt</c> existed, so the rollout has no blind window. Carries the device's
/// clock error and any CMTrace timezone skew.</item>
/// <item><c>StartedAt</c> — last resort when a session has no event stamp at all.</item>
/// </list>
/// </para>
/// Mixing the two frames is what let a live agent be marked Stalled: a session whose
/// IME-derived events were skewed -17 h looked silent for 17 hours the moment it started.
/// </summary>
/// <remarks>internal (not private) purely as a unit-test seam — it is a pure function
/// over its argument, pinned by <c>MaintenanceServerFrameLastContactTests</c>.</remarks>
internal static DateTime ServerFrameLastContact(SessionSummary session)
=> session.LastIngestAt ?? session.LastEventAt ?? session.StartedAt;
}
}
@@ -608,6 +608,20 @@ 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 });
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",
@@ -752,7 +752,12 @@ namespace AutopilotMonitor.Functions.Services
private (bool matched, object evidence) EvaluateAppInstallDurationCondition(RuleCondition condition, List<EnrollmentEvent> events)
{
var sortedEvents = events.OrderBy(e => e.Timestamp).ThenBy(e => e.Sequence).ToList();
// Ordering key is Sequence, never Timestamp: Sequence is a persisted, strictly
// monotonic per-session counter assigned at emit time and is immune to every clock
// problem, whereas Timestamp carries the device clock frame plus — for CMTrace-derived
// events — the writer process's timezone belief. Timestamp stays in use below only
// where an actual ELAPSED DURATION is meant, which is what it is for.
var sortedEvents = events.OrderBy(e => e.Sequence).ToList();
var completionEventTypes = string.IsNullOrWhiteSpace(condition.EventType)
? new HashSet<string>(new[] { "app_install_completed", "app_install_failed" }, StringComparer.OrdinalIgnoreCase)
@@ -774,7 +779,7 @@ namespace AutopilotMonitor.Functions.Services
var startEvent = sortedEvents.LastOrDefault(e =>
(string.Equals(e.EventType, "app_install_started", StringComparison.OrdinalIgnoreCase) ||
string.Equals(e.EventType, "app_install_start", StringComparison.OrdinalIgnoreCase)) &&
e.Timestamp <= completionEvent.Timestamp &&
e.Sequence <= completionEvent.Sequence &&
string.Equals(GetDataFieldValue(e, "appId") ?? GetDataFieldValue(e, "appName"), appKey, StringComparison.OrdinalIgnoreCase));
if (startEvent == null)
@@ -826,7 +831,12 @@ namespace AutopilotMonitor.Functions.Services
return (false, "event_correlation requires EventType, CorrelateEventType, and JoinField");
}
var sortedEvents = events.OrderBy(e => e.Timestamp).ThenBy(e => e.Sequence).ToList();
// Ordering key is Sequence, never Timestamp: Sequence is a persisted, strictly
// monotonic per-session counter assigned at emit time and is immune to every clock
// problem, whereas Timestamp carries the device clock frame plus — for CMTrace-derived
// events — the writer process's timezone belief. Timestamp stays in use below only
// where an actual ELAPSED DURATION is meant, which is what it is for.
var sortedEvents = events.OrderBy(e => e.Sequence).ToList();
// Collect Event A candidates with optional filter
var eventAList = sortedEvents
@@ -874,16 +884,14 @@ namespace AutopilotMonitor.Functions.Services
// Find the latest Event A that occurred before Event B
var matchingA = eventAByJoinKey[bKey]
.Where(a => a.Timestamp < eventB.Timestamp ||
(a.Timestamp == eventB.Timestamp && a.Sequence < eventB.Sequence))
.Where(a => a.Sequence < eventB.Sequence)
.Where(a =>
{
if (condition.TimeWindowSeconds == null || condition.TimeWindowSeconds <= 0)
return true;
return (eventB.Timestamp - a.Timestamp).TotalSeconds <= condition.TimeWindowSeconds.Value;
})
.OrderByDescending(a => a.Timestamp)
.ThenByDescending(a => a.Sequence)
.OrderByDescending(a => a.Sequence)
.FirstOrDefault();
if (matchingA == null)
@@ -698,9 +698,19 @@ namespace AutopilotMonitor.Functions.Services
var silenceCutoffStr = silenceCutoff.ToString("yyyy-MM-ddTHH:mm:ss");
var hardCutoffStr = hardCutoff.ToString("yyyy-MM-ddTHH:mm:ss");
// Candidate pre-filter across BOTH clock frames, deliberately permissive:
// LastIngestAt is the server frame (authoritative, but absent on rows written
// before it existed), LastEventAt the device frame (always present, but carries
// the device's clock error and any CMTrace timezone skew). An OR keeps a session
// in the candidate set when EITHER frame looks silent; the caller then makes the
// authoritative call on the server frame. Filtering on LastIngestAt alone would
// silently drop every pre-rollout row, since Table Storage does not match a
// filter against a missing property.
var filter = $"PartitionKey eq '{tenantId}' " +
$"and Status eq 'InProgress' " +
$"and LastEventAt lt datetime'{silenceCutoffStr}Z' " +
$"and (LastIngestAt lt datetime'{silenceCutoffStr}Z' " +
$"or LastEventAt lt datetime'{silenceCutoffStr}Z') " +
$"and (StartedAt ge datetime'{hardCutoffStr}Z' or ResumedAt ge datetime'{hardCutoffStr}Z')";
var query = tableClient.QueryAsync<TableEntity>(filter: filter);
@@ -772,7 +782,7 @@ namespace AutopilotMonitor.Functions.Services
var select = new[]
{
"PartitionKey", "RowKey", "Status", "StartedAt", "ResumedAt", "LastEventAt",
"SerialNumber", "IsPreProvisioned"
"LastIngestAt", "SerialNumber", "IsPreProvisioned"
};
var sessions = new List<SessionSummary>();
@@ -2338,6 +2338,14 @@ namespace AutopilotMonitor.Functions.Services
update["LastEventAt"] = EnsureUtc(latestEventTimestamp.Value);
}
// Server-frame ingest stamp. Reaching this method means a batch was just
// received, so "now" on the SERVER clock is the honest answer to "when did we
// last hear from this agent". LastEventAt above cannot answer that — it carries
// the device's clock frame and its timezone skew. Written unconditionally (not
// guarded by latestEventTimestamp) because an empty-timestamp batch is still
// contact from the agent.
update["LastIngestAt"] = EnsureUtc(DateTime.UtcNow);
// Increment script execution counters
if (platformScriptIncrement > 0)
{
@@ -3147,6 +3155,7 @@ namespace AutopilotMonitor.Functions.Services
// null as "CustomerSas" for back-compat.
DiagnosticsBlobDestination = entity.GetString("DiagnosticsBlobDestination"),
LastEventAt = SafeGetDateTime(entity, "LastEventAt"),
LastIngestAt = SafeGetDateTime(entity, "LastIngestAt"),
IsPreProvisioned = entity.GetBoolean("IsPreProvisioned") ?? false,
IsHybridJoin = entity.GetBoolean("IsHybridJoin") ?? false,
IsSelfDeployingProfile = entity.GetBoolean("IsSelfDeployingProfile") ?? false,
@@ -6,11 +6,41 @@ using System.Text.RegularExpressions;
namespace AutopilotMonitor.Shared.Logging
{
/// <summary>
/// Represents a single parsed line from a CMTrace-format log file
/// Represents a single parsed line from a CMTrace-format log file.
/// <para>
/// Timestamps are deliberately NOT resolved to UTC here unless the writer declared its own
/// offset. See <see cref="CmTraceLogParser"/> for why.
/// </para>
/// </summary>
public class CmTraceLogEntry
{
public DateTime Timestamp { get; set; }
/// <summary>
/// The line's local time exactly as the writing process wrote it. Kind is
/// <see cref="DateTimeKind.Unspecified"/> on purpose — this value is meaningless without
/// knowing which zone the WRITER believed it was in, which the line itself does not say.
/// </summary>
public DateTime LocalTimestamp { get; set; }
/// <summary>
/// The writer-declared UTC bias in minutes, when the line carried one ("+480").
/// <c>null</c> for the far more common bias-less form.
/// </summary>
public int? BiasMinutes { get; set; }
/// <summary>
/// UTC — populated ONLY when <see cref="BiasMinutes"/> was present, because a
/// writer-declared offset is authoritative. <c>null</c> otherwise: the caller must resolve
/// <see cref="LocalTimestamp"/> itself, and is the only party able to do so correctly.
/// </summary>
public DateTime? TimestampUtc { get; set; }
/// <summary>
/// Whether the line carried a parseable timestamp at all. When <c>false</c>,
/// <see cref="LocalTimestamp"/> is <c>default</c> and callers must fall back to their own
/// clock rather than treat the value as a real time.
/// </summary>
public bool HasTimestamp { get; set; }
public string Message { get; set; } = string.Empty;
public string Component { get; set; } = string.Empty;
public int Type { get; set; } // 1=Info, 2=Warning, 3=Error
@@ -21,12 +51,25 @@ namespace AutopilotMonitor.Shared.Logging
/// Parses CMTrace/SCCM log format used by IME and other Microsoft components.
/// Format: &lt;![LOG[{message}]LOG]!&gt;&lt;time="{time}" date="{date}" component="{comp}" context="" type="{type}" thread="{thread}" file=""&gt;
///
/// Lives in Shared because it is the SINGLE parsing implementation for both sides:
/// the agent's IME tracker / logparser gather collector (on-device) and the backend's
/// rules/gather/test-pattern endpoint, which must reproduce the agent's matching
/// semantics exactly so authors can test patterns without a device. Timestamp note:
/// bias-less lines parse with DateTimeStyles.AssumeLocal — on the backend that is the
/// SERVER's timezone, so the test endpoint reports match/parse results, not timestamps.
/// <para>
/// Lives in Shared because it is the SINGLE parsing implementation for both sides: the
/// agent's IME tracker / logparser gather collector (on-device) and the backend's
/// rules/gather/test-pattern endpoint, which must reproduce the agent's matching semantics
/// exactly so authors can test patterns without a device.
/// </para>
///
/// <para>
/// <b>The parser does not guess timezones.</b> A bias-less CMTrace line carries local time
/// and nothing else — IME 1.104 writes <c>DateTime.Now.TimeOfDay</c> in both of its trace
/// listeners. Resolving that with the READER's <c>TimeZoneInfo.Local</c> silently assumes the
/// writing and reading processes agree on the zone. They do not: each caches its zone at
/// process start and neither follows a later <c>tzutil</c> or a Windows auto-timezone change.
/// Field measurement over 11,068 sessions found 26 sessions where the two beliefs differed,
/// from +1 h to -17 h, silently shifting every IME-derived event by that amount. So this
/// parser hands back <see cref="CmTraceLogEntry.LocalTimestamp"/> plus
/// <see cref="CmTraceLogEntry.BiasMinutes"/> and lets the caller — which alone can measure
/// the writer's actual offset — do the conversion.
/// </para>
/// </summary>
public static class CmTraceLogParser
{
@@ -63,11 +106,24 @@ namespace AutopilotMonitor.Shared.Logging
var typeStr = match.Groups["type"].Value;
var thread = match.Groups["thread"].Value;
// Parse timestamp: date is "M-d-yyyy", time is "HH:mm:ss.ticks"
DateTime timestamp;
if (!TryParseTimestamp(dateStr, timeStr, biasStr, out timestamp))
DateTime localTimestamp;
var hasTimestamp = TryParseLocalTimestamp(dateStr, timeStr, out localTimestamp);
int? biasMinutes = null;
if (!string.IsNullOrEmpty(biasStr)
&& int.TryParse(biasStr, NumberStyles.AllowLeadingSign, CultureInfo.InvariantCulture, out var parsedBias))
{
timestamp = DateTime.UtcNow;
biasMinutes = parsedBias;
}
// A writer-declared bias is authoritative — it is the writer telling us its own
// offset, which is exactly the fact we otherwise have to measure.
// GetTimeZoneInformation convention: UTC = local + bias.
DateTime? timestampUtc = null;
if (hasTimestamp && biasMinutes.HasValue)
{
timestampUtc = DateTime.SpecifyKind(
localTimestamp.AddMinutes(biasMinutes.Value), DateTimeKind.Utc);
}
int type;
@@ -75,7 +131,10 @@ namespace AutopilotMonitor.Shared.Logging
entry = new CmTraceLogEntry
{
Timestamp = timestamp,
LocalTimestamp = localTimestamp,
BiasMinutes = biasMinutes,
TimestampUtc = timestampUtc,
HasTimestamp = hasTimestamp,
Message = message,
Component = component,
Type = type,
@@ -85,7 +144,26 @@ namespace AutopilotMonitor.Shared.Logging
return true;
}
private static bool TryParseTimestamp(string dateStr, string timeStr, string biasStr, out DateTime result)
/// <summary>
/// Resolves a bias-less CMTrace local timestamp using the READING process's own timezone.
///
/// <para>
/// <b>This is a fallback with a known defect, not a correct conversion.</b> It is right
/// only when the writing process happens to hold the same zone belief as this one. Use it
/// solely where no better information exists — a log this process does not tail and
/// therefore cannot measure an offset against — and mark the resulting value as not
/// source-grounded so the inaccuracy stays visible.
/// </para>
///
/// <para>
/// Callers that DO tail their log must instead measure the writer's offset from a freshly
/// appended line (see the agent's <c>CmTraceOffsetCalibrator</c>).
/// </para>
/// </summary>
public static DateTime ResolveUtcAssumingReaderZone(DateTime localTimestamp)
=> DateTime.SpecifyKind(localTimestamp, DateTimeKind.Local).ToUniversalTime();
private static bool TryParseLocalTimestamp(string dateStr, string timeStr, out DateTime result)
{
result = DateTime.MinValue;
@@ -129,29 +207,15 @@ namespace AutopilotMonitor.Shared.Logging
"M-d-yyyy HH:mm:ss"
};
// Bias-suffixed time ("+480"): the writer declared its own UTC offset in minutes
// (GetTimeZoneInformation convention: UTC = written time + bias). Honor it instead
// of assuming the agent's local timezone — writer and agent can disagree (mixed
// components, mid-enrollment timezone change; session df1fcf47).
if (!string.IsNullOrEmpty(biasStr)
&& int.TryParse(biasStr, NumberStyles.AllowLeadingSign, CultureInfo.InvariantCulture, out var biasMinutes))
{
if (DateTime.TryParseExact(combined, formats, CultureInfo.InvariantCulture,
DateTimeStyles.None, out result))
{
result = DateTime.SpecifyKind(result.AddMinutes(biasMinutes), DateTimeKind.Utc);
return true;
}
return false;
}
// No bias: CMTrace timestamps are in LOCAL time. Parse as local, then convert to UTC.
// DateTimeStyles.None: the value stays Unspecified. Attaching Local or Utc here would
// be the very guess this parser refuses to make.
if (DateTime.TryParseExact(combined, formats, CultureInfo.InvariantCulture,
DateTimeStyles.AssumeLocal, out result))
DateTimeStyles.None, out result))
{
result = result.ToUniversalTime();
return true;
}
result = default(DateTime);
return false;
}
}
@@ -349,6 +349,21 @@ namespace AutopilotMonitor.Shared.Models
/// </summary>
public DateTime? LastEventAt { get; set; }
/// <summary>
/// SERVER-side time of the most recent event ingest for this session.
/// <para>
/// <see cref="LastEventAt"/> lives in the DEVICE clock frame (it is the maximum
/// agent-supplied event timestamp). Comparing it against a server-derived cutoff mixes
/// two clock frames: a device whose clock runs slow — or one whose IME-derived events
/// carry a timezone skew — is judged silent far too early or not at all (measured in the
/// field: skews from -17 h to +1 h, see tasks/todo.md). This field is stamped from the
/// server clock on every ingest, so silence detection can compare like with like.
/// </para>
/// Null for sessions that predate this field — callers MUST fall back to
/// <see cref="LastEventAt"/> so rollout has no blind window.
/// </summary>
public DateTime? LastIngestAt { get; set; }
/// <summary>
/// Whether this session used WhiteGlove (Pre-Provisioning).
/// Set when a whiteglove_complete event is processed.
@@ -146,6 +146,11 @@ 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",
],
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>
@@ -146,6 +146,16 @@ describe("prepareReportModel", () => {
expect(model.failureCodes.moreCount).toBe(2);
});
it("keeps the full exit-code description untruncated", () => {
const model = prepareReportModel(
makeInput({
topFailureCodes: [{ code: "esp_apps_install_failure", exitCode: 1618, count: 1 }],
})
);
expect(model.failureCodes.rows[0][0]).toBe("esp_apps_install_failure");
expect(model.failureCodes.rows[0][2]).toBe("1618 (Another installation already in progress)");
});
it("enriches known error codes and labels unknown ones", () => {
const model = prepareReportModel(
makeInput({
@@ -215,10 +215,12 @@ export function prepareReportModel(input: AppReportInput): AppReportModel {
const failureCodeRows = analytics.topFailureCodes.slice(0, MAX_FAILURE_CODE_ROWS).map((row) => {
const entry = getErrorCodeEntry(row.code);
const exitEntry = row.exitCode != null ? getErrorCodeEntry(row.exitCode) : null;
// Full description on purpose — the PDF table wraps cells, and the exit-code
// text is exactly what the app owner needs to act on.
const exitDisplay =
row.exitCode != null
? exitEntry
? `${row.exitCode} (${exitEntry.description.slice(0, 24)}${exitEntry.description.length > 24 ? "…" : ""})`
? `${row.exitCode} (${exitEntry.description})`
: String(row.exitCode)
: "—";
return [
@@ -95,13 +95,12 @@ export function buildAppReportDoc(model: AppReportModel, generatedAt: Date): jsP
calloutBox(ctx, line);
}
sectionTitle(ctx, "Installs over time (success vs failure)");
ensureSpace(ctx, BAR_CHART_H + 2);
// keepWith = full chart height: a chart never separates from its title.
sectionTitle(ctx, "Installs over time (success vs failure)", BAR_CHART_H + 2);
drawStackedBarChart(doc, { x: pdfPage.margin, y: ctx.y, w: contentW, h: BAR_CHART_H }, model.timeSeries);
ctx.y += BAR_CHART_H + 2;
sectionTitle(ctx, "Avg Install Duration over time");
ensureSpace(ctx, LINE_CHART_H + 2);
sectionTitle(ctx, "Avg Install Duration over time", LINE_CHART_H + 2);
drawLineChart(doc, { x: pdfPage.margin, y: ctx.y, w: contentW, h: LINE_CHART_H }, model.timeSeries);
ctx.y += LINE_CHART_H + 2;
@@ -109,10 +108,10 @@ export function buildAppReportDoc(model: AppReportModel, generatedAt: Date): jsP
if (model.failureCodes.rows.length > 0) {
drawTable(ctx, {
columns: [
{ header: "Code", width: 30 },
{ header: "Description", width: 88 },
{ header: "Exit code", width: 44 },
{ header: "Count", width: 18, align: "right" },
{ header: "Code", width: 42 },
{ header: "Description", width: 62 },
{ header: "Exit code", width: 60 },
{ header: "Count", width: 16, align: "right" },
],
rows: model.failureCodes.rows,
moreCount: model.failureCodes.moreCount,
@@ -62,8 +62,13 @@ export function ensureSpace(ctx: PdfContext, needed: number) {
ctx.y = contentTop + 2;
}
export function sectionTitle(ctx: PdfContext, text: string) {
ensureSpace(ctx, 14);
/**
* Section heading with keep-with-next: `keepWith` reserves room for the first
* mm of the following block, so a title never strands alone at a page bottom
* while its table/chart starts on the next page.
*/
export function sectionTitle(ctx: PdfContext, text: string, keepWith = 20) {
ensureSpace(ctx, 14 + keepWith);
ctx.y += 3;
ctx.doc.setFont("helvetica", "bold");
ctx.doc.setFontSize(11);
@@ -142,6 +147,10 @@ export function calloutBox(ctx: PdfContext, text: string) {
const TABLE_HEADER_H = 7;
const TABLE_ROW_H = 6;
const TABLE_CELL_LINE_H = 3.6;
const TABLE_CELL_PAD_Y = 4.2;
/** Sanity cap so one pathological cell can't produce a page-tall row. */
const TABLE_MAX_CELL_LINES = 4;
function drawTableHeader(ctx: PdfContext, columns: TableColumn[]) {
ctx.doc.setFillColor(pdfColors.headerBand);
@@ -160,37 +169,66 @@ function drawTableHeader(ctx: PdfContext, columns: TableColumn[]) {
ctx.y += TABLE_HEADER_H;
}
/** Fixed-column table with zebra striping and header repetition after page breaks. */
/**
* Fixed-column table with zebra striping and header repetition after page
* breaks. Cells wrap onto multiple lines (up to TABLE_MAX_CELL_LINES, the last
* line ellipsized) so long descriptions stay fully readable.
*/
export function drawTable(ctx: PdfContext, spec: TableSpec) {
const { columns, rows, moreCount = 0, zebra = true } = spec;
ensureSpace(ctx, TABLE_HEADER_H + TABLE_ROW_H * 2);
drawTableHeader(ctx, columns);
ctx.doc.setFont("helvetica", "normal");
ctx.doc.setFontSize(8);
rows.forEach((row, rowIndex) => {
// Wrap every cell first so the row height is known before drawing.
const cellLines = row.map((cell, i) => {
const col = columns[i];
if (!col) return [] as string[];
const lines = ctx.doc.splitTextToSize(cell, col.width - 4) as string[];
if (lines.length > TABLE_MAX_CELL_LINES) {
const kept = lines.slice(0, TABLE_MAX_CELL_LINES);
kept[TABLE_MAX_CELL_LINES - 1] = truncateToWidth(
ctx.doc,
`${kept[TABLE_MAX_CELL_LINES - 1]}…`,
col.width - 4
);
return kept;
}
return lines;
});
const rowH = Math.max(
TABLE_ROW_H,
Math.max(...cellLines.map((l) => l.length), 1) * TABLE_CELL_LINE_H + 2.4
);
// Re-draw the header when the row would spill past the footer.
if (ctx.y + TABLE_ROW_H > contentBottom) {
ensureSpace(ctx, TABLE_HEADER_H + TABLE_ROW_H);
if (ctx.y + rowH > contentBottom) {
ensureSpace(ctx, TABLE_HEADER_H + rowH);
drawTableHeader(ctx, columns);
ctx.doc.setFont("helvetica", "normal");
ctx.doc.setFontSize(8);
}
if (zebra && rowIndex % 2 === 1) {
ctx.doc.setFillColor(pdfColors.zebra);
ctx.doc.rect(pdfPage.margin, ctx.y, contentW, TABLE_ROW_H, "F");
ctx.doc.rect(pdfPage.margin, ctx.y, contentW, rowH, "F");
}
ctx.doc.setFont("helvetica", "normal");
ctx.doc.setFontSize(8);
ctx.doc.setTextColor(pdfColors.text);
let x = pdfPage.margin;
row.forEach((cell, i) => {
cellLines.forEach((lines, i) => {
const col = columns[i];
if (!col) return;
const text = truncateToWidth(ctx.doc, cell, col.width - 4);
const tx = col.align === "right" ? x + col.width - 2 : x + 2;
ctx.doc.text(text, tx, ctx.y + 4.2, { align: col.align === "right" ? "right" : "left" });
lines.forEach((line, li) => {
ctx.doc.text(line, tx, ctx.y + TABLE_CELL_PAD_Y + li * TABLE_CELL_LINE_H, {
align: col.align === "right" ? "right" : "left",
});
});
x += col.width;
});
ctx.doc.setDrawColor(pdfColors.border);
ctx.doc.setLineWidth(0.1);
ctx.doc.line(pdfPage.margin, ctx.y + TABLE_ROW_H, pdfPage.margin + contentW, ctx.y + TABLE_ROW_H);
ctx.y += TABLE_ROW_H;
ctx.doc.line(pdfPage.margin, ctx.y + rowH, pdfPage.margin + contentW, ctx.y + rowH);
ctx.y += rowH;
});
if (moreCount > 0) {
ensureSpace(ctx, TABLE_ROW_H);
@@ -264,6 +264,10 @@ export const SHARED_MANIFEST = {
"name": "lastEventAt",
"optional": true
},
{
"name": "lastIngestAt",
"optional": true
},
{
"name": "isPreProvisioned",
"optional": false
@@ -260,6 +260,10 @@
"name": "lastEventAt",
"optional": true
},
{
"name": "lastIngestAt",
"optional": true
},
{
"name": "isPreProvisioned",
"optional": false
+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="">