From e9dba11b968db38b06bed5ccf3bd4aafd46eddd0 Mon Sep 17 00:00:00 2001 From: Oliver Kieselbach Date: Thu, 20 Aug 2026 13:49:14 +0200 Subject: [PATCH] fix(agent): resolve IME log timestamps with the writer's measured offset MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- .../ImeLogTrackerOffsetCalibrationTests.cs | 206 ++++++++++++++++++ .../Ime/ImeLogTracker.LogProcessing.cs | 73 ++++++- .../Enrollment/Ime/ImeLogTracker.cs | 18 ++ .../Enrollment/Ime/LogFilePositionTracker.cs | 12 + 4 files changed, 308 insertions(+), 1 deletion(-) create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerOffsetCalibrationTests.cs 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;