From 3b59dab2df6c29f13e09f167e1f8e76e8e8aaa6e Mon Sep 17 00:00:00 2001 From: Oliver Kieselbach Date: Thu, 20 Aug 2026 14:05:32 +0200 Subject: [PATCH] feat(agent): carry timestamp provenance on IME-derived events MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Every IME-sourced event now states what the writer wrote, what offset was applied, and how that offset was obtained: sourceLocalTs raw local time, verbatim, NO zone suffix sourceOffsetMinutes the offset subtracted sourceOffsetOrigin bias | calibrated | reader-zone-fallback Why: until now the only record of a conversion was the converted value, so a wrong offset was indistinguishable from a right one. Proving the field defect needed the diagnostics archive — and of the 5,386 sessions that went through a timezone change, essentially none had one, so the analysis had to fall back to median statistics across thousands of sessions to establish what one stored value makes obvious per session. It also makes a stored timestamp recomputable after the fact, without an agent release. No zone suffix on sourceLocalTs on purpose: the value genuinely carries none, and formatting one in would re-introduce the assumption this whole change removes. sourceOffsetMinutes is normalised to one sense (local = UTC + offset) across both origins. The wire bias uses the opposite GetTimeZoneInformation convention (UTC = local + bias), so a "+480" line is reported as -480; without that the field would flip sign depending on where the offset came from and be useless to compare. Added centrally in TagDerivedTimestamp, which all 14 emit sites already call, so this does not scatter through the adapter. DataJson only — no table schema change, so no Store/Map/seed chain and no backend deploy needed to start collecting it. Agent 2393 / backend 4313 green against a verified-clean build. Co-Authored-By: Claude Opus 5 (1M context) --- .../ImeLogTrackerOffsetCalibrationTests.cs | 66 +++++++++++++++++++ .../Ime/ImeLogTracker.LogProcessing.cs | 46 ++++++++++++- .../Enrollment/Ime/ImeLogTracker.cs | 19 ++++++ 3 files changed, 128 insertions(+), 3 deletions(-) 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 index 39f074cf..a3f2414e 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerOffsetCalibrationTests.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerOffsetCalibrationTests.cs @@ -202,5 +202,71 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime TimeSpan ignored; Assert.False(h.Tracker.OffsetCalibrator.TryGetOffset(LogFileName, out ignored)); } + + [Fact] + public async Task RecordsProvenance_ForACalibratedLine() + { + // P8: what the writer wrote, what we subtracted, and how we knew — the evidence that + // makes a stored timestamp recomputable without the diagnostics archive. + using var h = new Harness(); + var writerOffset = TimeSpan.FromHours(-7); // PST/PDT, the OOBE default + + 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(); + + h.Now = T0.AddSeconds(20); + var writtenAt = h.Now; + h.Append(Line("marker 3", writtenAt, writerOffset)); + await h.Pass(); + + Assert.Equal(CmTraceOffsetOrigin.Calibrated, h.Tracker.LastMatchedSourceOffsetOrigin); + Assert.Equal(-420, h.Tracker.LastMatchedSourceOffsetMinutes); + Assert.True(h.Tracker.LastMatchedSourceLocalTimestamp.HasValue); + + // The raw local value is kept verbatim, with no zone attached — attaching one would + // re-introduce exactly the assumption this change removes. + Assert.Equal(writtenAt + writerOffset, h.Tracker.LastMatchedSourceLocalTimestamp.Value); + Assert.Equal(DateTimeKind.Unspecified, h.Tracker.LastMatchedSourceLocalTimestamp.Value.Kind); + } + + [Fact] + public async Task RecordsProvenance_AsFallback_BeforeAnyCalibration() + { + // The warm-up pass: the offset is not measured yet, so the reader zone is assumed and + // the event has to say so rather than look source-grounded. + using var h = new Harness(); + + h.Append(Line("marker 1", h.Now, TimeSpan.FromHours(2))); + await h.Pass(); + + Assert.Equal(CmTraceOffsetOrigin.None, h.Tracker.LastMatchedSourceOffsetOrigin); + Assert.Null(h.Tracker.LastMatchedSourceOffsetMinutes); + Assert.True(h.Tracker.LastMatchedSourceLocalTimestamp.HasValue); + } + + [Fact] + public async Task RecordsProvenance_ForADeclaredBias() + { + using var h = new Harness(); + + h.Append(Line("marker 1", h.Now, TimeSpan.FromHours(2))); + await h.Pass(); + + h.Now = T0.AddSeconds(10); + var local = h.Now + TimeSpan.FromHours(-8); + h.Append($""); + await h.Pass(); + + Assert.Equal(CmTraceOffsetOrigin.Bias, h.Tracker.LastMatchedSourceOffsetOrigin); + // Reported in the same sense as a measured offset (local = UTC + offset), so the two + // origins are directly comparable; the wire bias uses the opposite convention. + Assert.Equal(-480, h.Tracker.LastMatchedSourceOffsetMinutes); + } + } } 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 2b888d79..d2f4404c 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 @@ -248,7 +248,22 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime private void HandlePatternMatch(CompiledPattern pattern, Match match, string message, CmTraceLogEntry entry) { LastMatchedPatternId = pattern.PatternId; - LastMatchedLogTimestamp = entry == null ? (DateTime?)null : ResolveEntryUtc(entry); + if (entry == null) + { + LastMatchedLogTimestamp = null; + LastMatchedSourceLocalTimestamp = null; + LastMatchedSourceOffsetMinutes = null; + LastMatchedSourceOffsetOrigin = CmTraceOffsetOrigin.None; + } + else + { + CmTraceOffsetOrigin origin; + int? offsetMinutes; + LastMatchedLogTimestamp = ResolveEntryUtc(entry, out origin, out offsetMinutes); + LastMatchedSourceLocalTimestamp = entry.HasTimestamp ? entry.LocalTimestamp : (DateTime?)null; + LastMatchedSourceOffsetMinutes = offsetMinutes; + LastMatchedSourceOffsetOrigin = origin; + } // Generic pattern-match hook (M4.4.4). Invoked before action-specific callbacks so // subscribers (e.g. ImeLogTrackerAdapter emitting WhiteGloveSealingPatternDetected) @@ -597,24 +612,49 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime /// private DateTime ResolveEntryUtc(CmTraceLogEntry entry) { + CmTraceOffsetOrigin origin; + int? offsetMinutes; + return ResolveEntryUtc(entry, out origin, out offsetMinutes); + } + + /// + /// Resolve a parsed entry to UTC and report HOW the offset was obtained, so the emitting + /// side can attach the evidence (P8). See . + /// + private DateTime ResolveEntryUtc(CmTraceLogEntry entry, out CmTraceOffsetOrigin origin, out int? offsetMinutes) + { + origin = CmTraceOffsetOrigin.None; + offsetMinutes = null; + if (entry == null) return UtcNowProvider(); // Writer declared its own offset — nothing left to measure. - if (entry.TimestampUtc.HasValue) return entry.TimestampUtc.Value; + if (entry.TimestampUtc.HasValue) + { + origin = CmTraceOffsetOrigin.Bias; + // Bias uses the GetTimeZoneInformation convention (UTC = local + bias); report the + // value in the same sense as a measured offset (local = UTC + offset). + offsetMinutes = entry.BiasMinutes.HasValue ? -entry.BiasMinutes.Value : (int?)null; + return entry.TimestampUtc.Value; + } if (!entry.HasTimestamp) return UtcNowProvider(); // Measured offset of the process that wrote this file. + TimeSpan measured; DateTime calibrated; if (_currentSourceFileName != null + && OffsetCalibrator.TryGetOffset(_currentSourceFileName, out measured) && OffsetCalibrator.TryResolveUtc(_currentSourceFileName, entry.LocalTimestamp, out calibrated)) { + origin = CmTraceOffsetOrigin.Calibrated; + offsetMinutes = (int)measured.TotalMinutes; 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. + // share our belief. Origin stays None so the emitted event says so. return CmTraceLogParser.ResolveUtcAssumingReaderZone(entry.LocalTimestamp); } 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 0c2499e8..3064ec52 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 @@ -209,6 +209,25 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime public string LastMatchedPatternId { get; internal set; } public DateTime? LastMatchedLogTimestamp { get; internal set; } + /// + /// Raw local time of the last matched line, exactly as the writer wrote it — no zone + /// attached, because the line carries none. + /// + /// Recorded so an emitted event can carry the evidence for its own timestamp. Without it + /// a conversion error is only provable from the diagnostics archive, and of the 5,386 + /// sessions that went through a timezone change essentially none had one — the field + /// analysis had to fall back to median statistics over thousands of sessions to show + /// what one stored value would have made obvious per session. + /// + /// + public DateTime? LastMatchedSourceLocalTimestamp { get; internal set; } + + /// Offset applied to , in minutes. + public int? LastMatchedSourceOffsetMinutes { get; internal set; } + + /// How that offset was arrived at — declared, measured, or neither. + public CmTraceOffsetOrigin LastMatchedSourceOffsetOrigin { get; internal set; } + // Callbacks to EnrollmentTracker public Action OnEspPhaseChanged { get; set; } public Action OnImeAgentVersion { get; set; }