From 34fd40c3ad0da3021dd50e27882b266bd0830d52 Mon Sep 17 00:00:00 2001 From: Oliver Kieselbach Date: Thu, 20 Aug 2026 20:18:35 +0200 Subject: [PATCH] fix(agent): refuse cross-file calibration anchors, make rejections visible MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Field forensics from the 1412 verification run (session 067797d8): the label/anchor crossing recurred on a provably genuine binary, and the new anchor-timestamp tripwire delivered — the "+02:00 measured for IntuneManagementExtension.log" anchor (local 19:51:26.948) does not exist in ANY log file on the device, and IME.log never produced its expected first measurement during 24 s of growing passes beforehand. Mechanism still unexplained; per-line anchoring keeps resolution immune (all 58 line-anchored events of the session were correct), but the observational layer must convict the culprit next time: - CalibrateFrom now receives the iteration's ACTUAL file name next to the calibration key. A mismatch — the smoking gun the two field occurrences imply but static analysis says is impossible — logs a Warning with both names plus the anchor, and refuses the anchor, so even the unexplained path can no longer poison the measurement store. - The first calibrator rejection per file logs at Debug (anchor local time + clock). The 24 s of silent non-measurement is exactly what made the phenomenon undiagnosable from the agent log. 232 IME tracker tests green against a verified-clean build. Co-Authored-By: Claude Fable 5 --- .../Ime/ImeLogTracker.LogProcessing.cs | 36 +++++++++++++++++-- 1 file changed, 34 insertions(+), 2 deletions(-) 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 944f609e..b6d87ae5 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 @@ -222,7 +222,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime // growing pass, during which lines fall back to the reader zone and are // flagged as such. if (hadPreviousObservation && calibrationAnchor != null) - CalibrateFrom(_currentSourceFileName, calibrationAnchor); + CalibrateFrom(_currentSourceFileName, Path.GetFileName(filePath), calibrationAnchor); } } catch (FileNotFoundException) { } @@ -701,18 +701,50 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime return CmTraceLogParser.ResolveUtcAssumingReaderZone(entry.LocalTimestamp); } + // Field-forensics (tripwire, 2026-08-20): sessions e9753578 and 067797d8 both logged a + // measurement whose LABEL and ANCHOR could not have come from the same file iteration — + // 067797d8's anchor value (19:51:26.948) does not even exist in ANY log file on the + // device, and IntuneManagementExtension.log never produced its expected first + // measurement at all. Mechanism unexplained; resolution is immune (per-line anchoring), + // but the observational layer must convict the culprit on the next occurrence. Hence: + // the stream's file name travels alongside the label (a mismatch is THE smoking gun), + // and the first rejected anchor per file becomes visible instead of silent. + private readonly HashSet _calibrationRejectLogged = new HashSet(StringComparer.OrdinalIgnoreCase); + /// /// 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) + /// The calibration key (_currentSourceFileName). + /// The file the enclosing iteration actually read. Must equal + /// — logged loudly when it does not (see tripwire note). + private void CalibrateFrom(string sourceFileName, string streamFileName, CmTraceLogEntry anchor) { + if (!string.Equals(sourceFileName, streamFileName, StringComparison.OrdinalIgnoreCase)) + { + _logger?.Warning( + $"ImeLogTracker: CALIBRATION LABEL MISMATCH — key='{sourceFileName}' but the iteration read '{streamFileName}' " + + $"(anchor local={anchor.LocalTimestamp:yyyy-MM-ddTHH:mm:ss.fffffff}). Skipping this anchor; see tripwire note."); + return; + } + TimeSpan previous; var hadOffset = OffsetCalibrator.TryGetOffset(sourceFileName, out previous); if (!OffsetCalibrator.TryCalibrate(sourceFileName, anchor.LocalTimestamp, UtcNowProvider())) + { + // Once per file: why a file that visibly grows never produces a measurement. + // 067797d8 ran 24 s of growing IME.log passes with no measurement at all — this + // silence is exactly what made the phenomenon undiagnosable from the log. + if (_calibrationRejectLogged.Add(sourceFileName)) + { + _logger?.Debug( + $"ImeLogTracker: {sourceFileName} anchor rejected by calibrator " + + $"(anchor local={anchor.LocalTimestamp:yyyy-MM-ddTHH:mm:ss.fffffff}, now={UtcNowProvider():HH:mm:ss.fff}Z) — first rejection for this file, further ones stay silent."); + } return; + } TimeSpan measured; if (!OffsetCalibrator.TryGetOffset(sourceFileName, out measured)) return;