Compare commits

...

9 Commits

Author SHA1 Message Date
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
23 changed files with 1335 additions and 97 deletions
@@ -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,274 @@
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: 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.
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.
Assert.Equal(-420, h.Tracker.LastMatchedMeasuredWriterOffsetMinutes);
// Applied: still the reader zone, and reported as such — never as "calibrated".
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,175 @@
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>Offset measured from a freshly appended line. See <see cref="CmTraceOffsetCalibrator"/>.</summary>
Calibrated = 2,
}
/// <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>
public bool TryCalibrate(string sourceKey, DateTime localTimestamp, DateTime agentUtcNow)
{
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);
// 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.
if ((candidate - offset).Duration() > MaxGridResidual) return false;
// Not a value any real timezone can produce.
if (offset < MinOffset || offset > MaxOffset) 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,6 +77,11 @@ 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.
var hadPreviousObservation = _positionTracker.HasSeen(filePath);
var startPos = _positionTracker.GetSafePosition(filePath, fileInfo.Length);
if (startPos >= fileInfo.Length)
{
@@ -86,6 +94,13 @@ 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);
// 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 +162,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 +177,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 +202,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 +248,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 +288,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 +575,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 +602,105 @@ 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();
// REVERTED 2026-08-20 (session e9753578): the measured offset is NOT applied.
//
// 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 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.
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;
var readerZoneOffset = TimeZoneInfo.Local.GetUtcOffset(UtcNowProvider());
if (measured == readerZoneOffset)
{
_logger?.Debug(
$"ImeLogTracker: {sourceFileName} writer offset measured {measured} (matches this process).");
return;
}
_logger?.Info(
$"ImeLogTracker: {sourceFileName} writer offset measured {measured}, this process believes {readerZoneOffset} " +
$"— timestamps from this file are corrected by {(measured - readerZoneOffset).Negate()}.");
}
}
}
@@ -85,6 +85,24 @@ 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;
internal static DateTime NormalizeUtc(DateTime value) =>
value.Kind == DateTimeKind.Utc ? value : DateTime.SpecifyKind(value, DateTimeKind.Utc);
@@ -191,6 +209,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;
@@ -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,66 @@ 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";
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.
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));
}
}
}
@@ -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;
}
}
@@ -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,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