Compare commits

...

8 Commits

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

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

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

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

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
2026-08-20 19:28:54 +02:00
Oliver Kieselbach c728a0bd41 feat(backend): surface genuine agent binary-integrity mismatches as ops events
IntegrityCheckFailed emergency reports used to land in App Insights
only — session e9753578's agent reported a hash mismatch and no product
surface showed it, which cost a day of mis-attributed root-causing.
They now materialize as an AgentBinaryIntegrityMismatch ops event
(Warning, Agent category, dual-registered in the web alert-rule
catalog per feedback_ops_event_types_dual_register).

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

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

Backend suite 4320 green, web tsc clean.

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

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

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

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

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

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

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

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

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

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

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

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

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

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

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-08-20 17:47:15 +02:00
Oliver Kieselbach eda61eaade Fix Tenant Groups layout overflowing on phones (#132) 2026-08-20 15:27:08 +02:00
18 changed files with 1194 additions and 63 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();
}
}
}
}
@@ -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;
}
}
@@ -88,13 +88,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
[InlineData(0)] // UTC
public async Task MeasuresTheWritersOffsetExactly_ForAnyBelief(int writerOffsetHours)
{
// NOTE: this used to assert that a line written at T RESOLVES to T. That application
// was reverted on 2026-08-20 after session e9753578: one offset per file is wrong when
// a file holds two writer eras (IME restarting across a timezone change), which shifted
// 5 script_started events by -9 h while their completions stayed correct and inflated
// every script duration to ~32,400 s. Until the calibrator is era-aware, the measured
// offset is observational and the reader-zone fallback is applied uniformly — wrong in
// absolute terms but self-consistent, so derived durations stay right.
// 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();
@@ -222,10 +221,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
h.Append(Line("marker 3", h.Now, writerOffset));
await h.Pass();
// Measured: the writer's actual belief.
// Measured: the writer's actual belief, per file.
Assert.Equal(-420, h.Tracker.LastMatchedMeasuredWriterOffsetMinutes);
// Applied: still the reader zone, and reported as such — never as "calibrated".
// 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);
}
@@ -12,8 +12,21 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
/// <summary>The writer declared its offset in the line ("+480"). Authoritative.</summary>
Bias = 1,
/// <summary>Offset measured from a freshly appended line. See <see cref="CmTraceOffsetCalibrator"/>.</summary>
/// <summary>
/// A per-FILE measured offset was applied. Retired by the 2026-08-20 revert (04b1a7c6):
/// one offset per file is wrong when a file holds lines from two writer eras. Kept so
/// stored events from agent 2.0.1410 remain interpretable.
/// </summary>
Calibrated = 2,
/// <summary>
/// The line anchored ITSELF: it was read in a pass whose lines are provably fresh
/// (written since the previous poll), so its own distance to the agent clock, rounded
/// to the 15-minute offset grid, IS the writer's offset — no cross-line state involved.
/// Immune to interleaved writer eras by construction. See
/// <see cref="CmTraceOffsetCalibrator.TryMeasureOffset"/>.
/// </summary>
LineAnchored = 3,
}
/// <summary>
@@ -98,24 +111,51 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
/// <param name="localTimestamp">The line's local time exactly as written (Kind is ignored).</param>
/// <param name="agentUtcNow">The agent's UTC clock at parse time.</param>
/// <returns><c>true</c> when the anchor was accepted and the offset updated.</returns>
public bool TryCalibrate(string sourceKey, DateTime localTimestamp, DateTime agentUtcNow)
/// <summary>
/// The pure measurement: the distance between a FRESH line's local time and the agent's
/// UTC clock, rounded to the 15-minute offset grid, is the writer's UTC offset.
/// <para>
/// Freshness is the caller's obligation and is what makes this correct — for a line
/// written within the last poll interval, <c>local - now</c> differs from the writer's
/// true offset only by seconds, which the grid rounding absorbs. Returns <c>false</c>
/// when the residual exceeds <see cref="MaxGridResidual"/> (the line is not fresh, or
/// the writer's clock is broken) or the rounded value is not a real timezone offset.
/// </para>
/// <para>
/// Known, accepted edge: a freshly WRITTEN line carrying an old REPLAYED timestamp whose
/// age happens to sit within the residual of an exact grid multiple measures that age as
/// an "offset" — the line then resolves to roughly the read time instead of its replayed
/// past. The error is bounded by construction (an anchored line always resolves to
/// now ± <see cref="MaxGridResidual"/>), the case needs an age of exactly N×15 min ± 2 min,
/// and sub-24h replays are treated as current by the historic-replay guard anyway.
/// </para>
/// </summary>
public static bool TryMeasureOffset(DateTime localTimestamp, DateTime agentUtcNow, out TimeSpan offset)
{
if (string.IsNullOrEmpty(sourceKey)) return false;
var candidate = DateTime.SpecifyKind(localTimestamp, DateTimeKind.Unspecified)
- DateTime.SpecifyKind(agentUtcNow, DateTimeKind.Unspecified);
var gridUnits = Math.Round(candidate.TotalMinutes / OffsetGrid.TotalMinutes,
MidpointRounding.AwayFromZero);
var offset = TimeSpan.FromMinutes(gridUnits * OffsetGrid.TotalMinutes);
offset = TimeSpan.FromMinutes(gridUnits * OffsetGrid.TotalMinutes);
// Off-grid by more than the tolerance: the anchor was not fresh, or the writer's own
// clock is broken. Either way it must not become the offset.
// Off-grid by more than the tolerance: the line was not fresh, or the writer's own
// clock is broken. Either way it must not become an offset.
if ((candidate - offset).Duration() > MaxGridResidual) return false;
// Not a value any real timezone can produce.
if (offset < MinOffset || offset > MaxOffset) return false;
return true;
}
public bool TryCalibrate(string sourceKey, DateTime localTimestamp, DateTime agentUtcNow)
{
if (string.IsNullOrEmpty(sourceKey)) return false;
TimeSpan offset;
if (!TryMeasureOffset(localTimestamp, agentUtcNow, out offset)) return false;
lock (_lock)
{
if (_bySource.TryGetValue(sourceKey, out var existing))
@@ -77,12 +77,21 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
var fileInfo = new FileInfo(filePath);
if (!fileInfo.Exists) continue;
// Captured BEFORE GetSafePosition, which creates the entry as a side effect.
// Growth measured against a previously observed size is what makes the last
// line of this pass a valid "written now" calibration anchor.
// Captured BEFORE MarkChecked below stamps this pass. Growth measured
// against a previously observed state is what makes this pass's lines valid
// "written now" anchors — for the per-file measurement AND per-line anchoring.
var hadPreviousObservation = _positionTracker.HasSeen(filePath);
var lastCheckedUtc = _positionTracker.GetLastCheckedUtc(filePath);
var passNowUtc = UtcNowProvider();
var startPos = _positionTracker.GetSafePosition(filePath, fileInfo.Length);
// Every look counts, including "no new data" and an empty first sight: the
// NEXT pass's freshness window is measured from here. Restored bookmarks
// deliberately carry no LastCheckedUtc — the first pass after a restart reads
// downtime backlog and must never count as fresh.
_positionTracker.MarkChecked(filePath, passNowUtc);
if (startPos >= fileInfo.Length)
{
// M2: guard the interpolated string so it isn't built every 100 ms tick
@@ -95,6 +104,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
_logger.Trace($"ImeLogTracker: reading {Path.GetFileName(filePath)} from pos {startPos} (size={fileInfo.Length}, delta={fileInfo.Length - startPos})");
_currentSourceFileName = Path.GetFileName(filePath);
_currentPassLinesAreFresh = hadPreviousObservation
&& lastCheckedUtc > DateTime.MinValue
&& (passNowUtc - lastCheckedUtc) <= FreshLineMaxAge;
// Newest bias-less line of this pass — the calibration anchor. Bias-carrying
// lines are skipped: they already state the writer's offset, so they need no
@@ -210,7 +222,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
// growing pass, during which lines fall back to the reader zone and are
// flagged as such.
if (hadPreviousObservation && calibrationAnchor != null)
CalibrateFrom(_currentSourceFileName, calibrationAnchor);
CalibrateFrom(_currentSourceFileName, Path.GetFileName(filePath), calibrationAnchor);
}
}
catch (FileNotFoundException) { }
@@ -650,56 +662,110 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
if (!entry.HasTimestamp) return UtcNowProvider();
// REVERTED 2026-08-20 (session e9753578): the measured offset is NOT applied.
// ERA-AWARE RESOLUTION (2026-08-20, second attempt): a FRESH line anchors ITSELF.
//
// Calibration keeps one offset per FILE, but a single log 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 is wrong. In
// the field that shifted 5 script_started events by -9 h while their script_completed
// counterparts were resolved correctly, inflating every script duration to ~32,400 s.
// 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.
//
// The deeper lesson: applying the reader zone uniformly is wrong for ABSOLUTE times
// but self-consistent for DERIVED ones — 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. Until the calibrator is era-aware
// (see tasks/todo.md), uniform beats partially-correct.
//
// The measurement itself still runs: it costs nothing, feeds the Info log and the
// event provenance, and is the field data the era-aware fix will be built on.
// 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);
}
// Field-forensics (tripwire, 2026-08-20): sessions e9753578 and 067797d8 both logged a
// measurement whose LABEL and ANCHOR could not have come from the same file iteration —
// 067797d8's anchor value (19:51:26.948) does not even exist in ANY log file on the
// device, and IntuneManagementExtension.log never produced its expected first
// measurement at all. Mechanism unexplained; resolution is immune (per-line anchoring),
// but the observational layer must convict the culprit on the next occurrence. Hence:
// the stream's file name travels alongside the label (a mismatch is THE smoking gun),
// and the first rejected anchor per file becomes visible instead of silent.
private readonly HashSet<string> _calibrationRejectLogged = new HashSet<string>(StringComparer.OrdinalIgnoreCase);
/// <summary>
/// Feed the pass's newest bias-less line to the calibrator and report a measured offset
/// that disagrees with this process's own zone — that disagreement is precisely the
/// condition that used to corrupt every IME-derived timestamp silently.
/// </summary>
private void CalibrateFrom(string sourceFileName, CmTraceLogEntry anchor)
/// <param name="sourceFileName">The calibration key (<c>_currentSourceFileName</c>).</param>
/// <param name="streamFileName">The file the enclosing iteration actually read. Must equal
/// <paramref name="sourceFileName"/> — logged loudly when it does not (see tripwire note).</param>
private void CalibrateFrom(string sourceFileName, string streamFileName, CmTraceLogEntry anchor)
{
if (!string.Equals(sourceFileName, streamFileName, StringComparison.OrdinalIgnoreCase))
{
_logger?.Warning(
$"ImeLogTracker: CALIBRATION LABEL MISMATCH — key='{sourceFileName}' but the iteration read '{streamFileName}' " +
$"(anchor local={anchor.LocalTimestamp:yyyy-MM-ddTHH:mm:ss.fffffff}). Skipping this anchor; see tripwire note.");
return;
}
TimeSpan previous;
var hadOffset = OffsetCalibrator.TryGetOffset(sourceFileName, out previous);
if (!OffsetCalibrator.TryCalibrate(sourceFileName, anchor.LocalTimestamp, UtcNowProvider()))
{
// Once per file: why a file that visibly grows never produces a measurement.
// 067797d8 ran 24 s of growing IME.log passes with no measurement at all — this
// silence is exactly what made the phenomenon undiagnosable from the log.
if (_calibrationRejectLogged.Add(sourceFileName))
{
_logger?.Debug(
$"ImeLogTracker: {sourceFileName} anchor rejected by calibrator " +
$"(anchor local={anchor.LocalTimestamp:yyyy-MM-ddTHH:mm:ss.fffffff}, now={UtcNowProvider():HH:mm:ss.fff}Z) — first rejection for this file, further ones stay silent.");
}
return;
}
TimeSpan measured;
if (!OffsetCalibrator.TryGetOffset(sourceFileName, out measured)) return;
if (hadOffset && measured == previous) return;
// The anchor's local timestamp is part of the record ON PURPOSE (tripwire, 2026-08-20):
// session e9753578 logged "+02:00 measured for IntuneManagementExtension.log" although
// that file provably held no +2-era line — an anchor/label pairing the committed code
// could not be shown to produce. Should it ever happen again, the logged anchor value
// itself will prove (or refute) the crossing without needing the device's log files.
var readerZoneOffset = TimeZoneInfo.Local.GetUtcOffset(UtcNowProvider());
if (measured == readerZoneOffset)
{
_logger?.Debug(
$"ImeLogTracker: {sourceFileName} writer offset measured {measured} (matches this process).");
$"ImeLogTracker: {sourceFileName} writer offset measured {measured} (matches this process, anchor local={anchor.LocalTimestamp:yyyy-MM-ddTHH:mm:ss.fff}).");
return;
}
_logger?.Info(
$"ImeLogTracker: {sourceFileName} writer offset measured {measured}, this process believes {readerZoneOffset} " +
$"— timestamps from this file are corrected by {(measured - readerZoneOffset).Negate()}.");
$"(anchor local={anchor.LocalTimestamp:yyyy-MM-ddTHH:mm:ss.fff}). Measurement is observational — resolution anchors per line.");
}
}
@@ -103,6 +103,24 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
/// </summary>
private string _currentSourceFileName;
/// <summary>
/// Whether every line of the file iteration currently in flight is provably FRESH —
/// written after the previous look at this file, which happened at most
/// <see cref="FreshLineMaxAge"/> ago in THIS process. Only then may a line anchor its
/// own UTC offset (<see cref="CmTraceOffsetCalibrator.TryMeasureOffset"/>): the grid
/// rounding is safe when the line's age is bounded by seconds, and becomes a trap on
/// backlog whose age can hit an exact grid multiple. Same single-task justification as
/// <see cref="_currentSourceFileName"/>.
/// </summary>
private bool _currentPassLinesAreFresh;
/// <summary>
/// Maximum gap between two looks at a file for its new bytes to count as fresh. Far
/// above the 100 ms poll (rides out GC pauses and ESP CPU starvation), far below the
/// 13-minute danger zone where a line's AGE could round onto the 15-minute offset grid.
/// </summary>
internal static readonly TimeSpan FreshLineMaxAge = TimeSpan.FromSeconds(30);
internal static DateTime NormalizeUtc(DateTime value) =>
value.Kind == DateTimeKind.Utc ? value : DateTime.SpecifyKind(value, DateTimeKind.Utc);
@@ -65,6 +65,42 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
state.LastReadTime = DateTime.UtcNow;
}
/// <summary>
/// Records that the file was looked at in a poll pass — whether or not it had new data.
/// Creates the entry on first sight (position 0), so a file first seen EMPTY counts as
/// observed and its first content is provably fresh.
/// <para>
/// This timestamp is the freshness reference for per-line offset anchoring: bytes found
/// in the NEXT pass were written after this instant, so
/// <c>now - LastCheckedUtc</c> bounds the age of every line in that pass's chunk.
/// The caller supplies the clock (the tracker's <c>UtcNowProvider</c>) so replay/test
/// clocks stay consistent with the freshness comparison.
/// </para>
/// </summary>
public void MarkChecked(string filePath, DateTime nowUtc)
{
FilePositionState state;
if (!_positions.TryGetValue(filePath, out state))
{
state = new FilePositionState();
_positions[filePath] = state;
}
state.LastCheckedUtc = nowUtc;
}
/// <summary>
/// When the file was last looked at, or <see cref="DateTime.MinValue"/> when it never
/// was in THIS process — including entries restored from persisted state, whose
/// bookmark survives an agent restart but whose freshness deliberately does not
/// (the restart gap can hold arbitrarily old backlog).
/// </summary>
public DateTime GetLastCheckedUtc(string filePath)
{
FilePositionState state;
return _positions.TryGetValue(filePath, out state) ? state.LastCheckedUtc : DateTime.MinValue;
}
/// <summary>
/// Gets the stored position for a file, or 0 if not tracked.
/// Does not perform rollover detection.
@@ -89,6 +125,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
/// <summary>
/// Restores a previously persisted position for a file.
/// Used on agent restart to continue reading from the last known position.
/// <para>
/// <see cref="FilePositionState.LastCheckedUtc"/> is deliberately NOT restored: the
/// bookmark survives the restart, the freshness guarantee does not — the first pass
/// after a restart reads the whole downtime backlog and must never anchor per-line
/// offsets on it.
/// </para>
/// </summary>
public void RestorePosition(string filePath, long position, long lastKnownSize)
{
@@ -96,7 +138,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
{
Position = position,
LastKnownSize = lastKnownSize,
LastReadTime = DateTime.UtcNow
LastReadTime = DateTime.UtcNow,
LastCheckedUtc = DateTime.MinValue
};
}
}
@@ -106,5 +149,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
public long Position { get; set; }
public long LastKnownSize { get; set; }
public DateTime LastReadTime { get; set; }
/// <summary>
/// When this file was last looked at by a poll pass IN THIS PROCESS. In-memory only —
/// never persisted, so a restart resets it (see <see cref="LogFilePositionTracker.RestorePosition"/>).
/// </summary>
public DateTime LastCheckedUtc { get; set; }
}
}
@@ -427,11 +427,14 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
switch (origin)
{
case CmTraceOffsetOrigin.Bias: return "bias";
// Per-FILE offset application, retired by the 2026-08-20 revert (04b1a7c6).
// Kept so stored 2.0.1410 events remain interpretable; no current path emits it.
case CmTraceOffsetOrigin.Calibrated: return "calibrated";
// Unreachable since the 2026-08-20 revert; kept so the vocabulary survives the
// era-aware fix rather than being reinvented.
// The writer's offset was never measured, so this process's own zone was assumed —
// correct only if the writer happens to share it.
// The line anchored itself: read provably fresh, its own distance to the agent
// clock (grid-rounded) was applied as the writer's offset. Era-safe per line.
case CmTraceOffsetOrigin.LineAnchored: return "line-anchored";
// The line was not provably fresh (backlog, restart catch-up, replay), so this
// process's own zone was assumed — correct only if the writer happens to share it.
default: return "reader-zone-fallback";
}
}
@@ -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
@@ -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",
@@ -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>
+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="">