diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerOffsetCalibrationTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerOffsetCalibrationTests.cs new file mode 100644 index 00000000..39f074cf --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerOffsetCalibrationTests.cs @@ -0,0 +1,206 @@ +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 +{ + /// + /// End-to-end offset calibration through a real read cycle. + /// + /// + /// 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. + /// + /// + /// + /// 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). + /// + /// + 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 Patterns() => new List + { + new ImeLogPattern + { + PatternId = "T-MARK", Category = "always", Enabled = true, + Pattern = @"marker (?\d+)", + Action = "noop", + Parameters = new Dictionary(), + }, + }; + + /// A CMTrace line as a writer holding renders instant . + private static string Line(string message, DateTime utcInstant, TimeSpan writerOffset) + { + var local = utcInstant + writerOffset; + return $""; + } + + 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. Whatever it is, a line written at T must come back as T. + [InlineData(2)] // CEST — the bfff9b1c writer, while the agent still believed BST + [InlineData(1)] // BST — writer and a UK-defaulted agent agreeing + [InlineData(-7)] // PDT — the OOBE default behind the -17 h sessions + [InlineData(10)] // E. Australia + [InlineData(0)] // UTC + public async Task ResolvesLineToTheInstantItWasWritten_ForAnyWriterBelief(int writerOffsetHours) + { + var writerOffset = TimeSpan.FromHours(writerOffsetHours); + using var h = new Harness(); + + // Pass 1 — first sight of the file. Its content may be arbitrarily old, so nothing is + // calibrated from it. + h.Append(Line("marker 1", h.Now, writerOffset)); + await h.Pass(); + + // Pass 2 — the file has grown against a size we already observed, so this line was + // written within a poll interval and is a valid anchor. + h.Now = T0.AddSeconds(10); + h.Append(Line("marker 2", h.Now, writerOffset)); + await h.Pass(); + + // Pass 3 — resolved with the measured offset. + h.Now = T0.AddSeconds(20); + var writtenAt = h.Now; + h.Append(Line("marker 3", writtenAt, writerOffset)); + await h.Pass(); + + Assert.True(h.Tracker.LastMatchedLogTimestamp.HasValue); + Assert.Equal(writtenAt, h.Tracker.LastMatchedLogTimestamp.Value); + } + + [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); + Assert.True(h.Tracker.LastMatchedLogTimestamp.HasValue); + Assert.Equal(writtenAt, h.Tracker.LastMatchedLogTimestamp.Value); + } + + [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($""); + 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)); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.LogProcessing.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.LogProcessing.cs index 4b0149db..2b888d79 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.LogProcessing.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.LogProcessing.cs @@ -42,7 +42,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime return false; } - private async Task CheckLogFilesAsync(CancellationToken token) + /// 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. + 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 { @@ -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) { } @@ -572,10 +598,55 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime private DateTime ResolveEntryUtc(CmTraceLogEntry entry) { if (entry == null) return UtcNowProvider(); + + // Writer declared its own offset — nothing left to measure. if (entry.TimestampUtc.HasValue) return entry.TimestampUtc.Value; + if (!entry.HasTimestamp) return UtcNowProvider(); + + // Measured offset of the process that wrote this file. + DateTime calibrated; + if (_currentSourceFileName != null + && OffsetCalibrator.TryResolveUtc(_currentSourceFileName, entry.LocalTimestamp, out calibrated)) + { + return calibrated; + } + + // Not calibrated yet (first growing pass, or a file that never grows while we watch). + // Falls back to this process's zone, which is right only if the writer happens to + // share our belief. Emissions built on this are flagged as not source-grounded. return CmTraceLogParser.ResolveUtcAssumingReaderZone(entry.LocalTimestamp); } + /// + /// 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. + /// + 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()}."); + } + } } diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.cs index db808e2f..0c2499e8 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.cs @@ -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. /// + /// + /// Measures the UTC offset the IME process believes it is in, per log file. + /// + /// 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). + /// + /// + internal CmTraceOffsetCalibrator OffsetCalibrator { get; } = new CmTraceOffsetCalibrator(); + + /// + /// 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 ResolveEntryUtc + /// and the handlers the calibration key without threading it through every signature. + /// + private string _currentSourceFileName; + internal static DateTime NormalizeUtc(DateTime value) => value.Kind == DateTimeKind.Utc ? value : DateTime.SpecifyKind(value, DateTimeKind.Utc); diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/LogFilePositionTracker.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/LogFilePositionTracker.cs index 79b3e4a6..46483845 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/LogFilePositionTracker.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/LogFilePositionTracker.cs @@ -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. /// + /// + /// Whether this file was already observed in an earlier pass. + /// + /// 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. + /// + /// + public bool HasSeen(string filePath) => _positions.ContainsKey(filePath); + public long GetSafePosition(string filePath, long currentFileSize) { FilePositionState state;