gsadmin/AutopilotMonitor
1
0
Fork 0
mirror of https://github.com/okieselbach/AutopilotMonitor.git synced 2026-10-24 12:42:38 +00:00
Code Issues Packages Projects Releases Wiki Activity

feat(agent): measure the CMTrace writer's UTC offset instead of assuming it

Browse Source 
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>
This commit is contained in:
Oliver Kieselbach
2026-08-20 13:25:48 +02:00
parent aaacc6ecb2
commit 93a42ba5e4
2 changed files with 365 additions and 0 deletions
Download Patch File Download Diff File Expand all files Collapse all files
src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/CmTraceOffsetCalibratorTests.cs
+190
View File
@@ -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));
}
}
}
src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/CmTraceOffsetCalibrator.cs
+175
View File
@@ -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;
}
}
}