diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/CmTraceOffsetCalibratorTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/CmTraceOffsetCalibratorTests.cs new file mode 100644 index 00000000..3e453a60 --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/CmTraceOffsetCalibratorTests.cs @@ -0,0 +1,190 @@ +using System; +using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime; +using Xunit; + +namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime +{ + /// + /// Pins the measurement contract of . + /// + /// + /// 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. + /// + /// + public class CmTraceOffsetCalibratorTests + { + private const string Source = "IntuneManagementExtension.log"; + private static readonly DateTime UtcNow = new DateTime(2026, 08, 20, 07, 31, 46, DateTimeKind.Utc); + + /// A line written "now" by a writer that believes it is at . + 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: + // 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)); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/CmTraceOffsetCalibrator.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/CmTraceOffsetCalibrator.cs new file mode 100644 index 00000000..a0cf7cae --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/CmTraceOffsetCalibrator.cs @@ -0,0 +1,175 @@ +using System; +using System.Collections.Generic; + +namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime +{ + /// How the UTC value of a CMTrace line was arrived at. Recorded as evidence. + public enum CmTraceOffsetOrigin + { + /// No offset known — the caller fell back to its own clock. + None = 0, + + /// The writer declared its offset in the line ("+480"). Authoritative. + Bias = 1, + + /// Offset measured from a freshly appended line. See . + Calibrated = 2, + } + + /// + /// Measures the UTC offset that the process WRITING a CMTrace log believes it is in. + /// + /// + /// A CMTrace line carries local time and no offset — IME 1.104 writes + /// DateTime.Now.TimeOfDay in both of its trace listeners. Converting such a line with + /// the agent's own TimeZoneInfo.Local assumes the two processes agree, and they do not: + /// both cache their zone at process start and neither follows a later tzutil or a + /// Windows auto-timezone change. The resulting error is + /// Offset_writer - Offset_agent 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). + /// + /// + /// + /// 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": + /// + /// candidate = lineLocalTime - agentUtcNow + /// offset = round(candidate / 15 min) * 15 min + /// lineUtc = lineLocalTime - offset + /// + /// Every real UTC offset is a whole multiple of 15 minutes, so the rounding absorbs poll and + /// flush latency without ambiguity. + /// + /// + /// + /// 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. + /// + /// + /// + /// 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. + /// + /// + public sealed class CmTraceOffsetCalibrator + { + /// Grid that every real UTC offset sits on. + internal static readonly TimeSpan OffsetGrid = TimeSpan.FromMinutes(15); + + /// + /// 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. + /// + internal static readonly TimeSpan MaxGridResidual = TimeSpan.FromMinutes(2); + + /// Real UTC offsets span UTC-12 (Dateline) to UTC+14 (Line Islands). + internal static readonly TimeSpan MinOffset = TimeSpan.FromHours(-12); + + /// Upper bound of a real UTC offset. See . + 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 _bySource = + new Dictionary(StringComparer.OrdinalIgnoreCase); + + /// + /// Offer a freshly appended line as a calibration anchor. + /// + /// 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. + /// + /// + /// Log file identity; the file name is enough. + /// The line's local time exactly as written (Kind is ignored). + /// The agent's UTC clock at parse time. + /// true when the anchor was accepted and the offset updated. + 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; + } + + /// The offset measured for this source, when one has been established. + 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; + } + } + + /// + /// Convert a line's local time to UTC using the measured offset. Returns false when + /// this source has not been calibrated yet — the caller then picks its own fallback and + /// should mark the result as not source-grounded. + /// + 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; + } + } +}