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 a3f2414e..7c535caa 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
@@ -80,36 +80,34 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
}
[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
+ // The writer's belief. The MEASUREMENT must recover it exactly, whatever it is.
+ [InlineData(2)] // CEST
+ [InlineData(1)] // BST
+ [InlineData(-7)] // PDT — the OOBE default behind the -17 h and -9 h field cases
[InlineData(10)] // E. Australia
[InlineData(0)] // UTC
- public async Task ResolvesLineToTheInstantItWasWritten_ForAnyWriterBelief(int writerOffsetHours)
+ public async Task MeasuresTheWritersOffsetExactly_ForAnyBelief(int writerOffsetHours)
{
+ // NOTE: this used to assert that a line written at T RESOLVES to T. That application
+ // was reverted on 2026-08-20 after session e9753578: one offset per file is wrong when
+ // a file holds two writer eras (IME restarting across a timezone change), which shifted
+ // 5 script_started events by -9 h while their completions stayed correct and inflated
+ // every script duration to ~32,400 s. Until the calibrator is era-aware, the measured
+ // offset is observational and the reader-zone fallback is applied uniformly — wrong in
+ // absolute terms but self-consistent, so derived durations stay right.
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);
+ TimeSpan measured;
+ Assert.True(h.Tracker.OffsetCalibrator.TryGetOffset(LogFileName, out measured));
+ Assert.Equal(writerOffset, measured);
}
[Fact]
@@ -175,8 +173,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
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);
+ // The measurement follows the restart. Applying it is what the 2026-08-20 revert
+ // removed — that is exactly the case a file with two writer eras breaks.
+ Assert.Equal(120, h.Tracker.LastMatchedMeasuredWriterOffsetMinutes);
}
[Fact]
@@ -204,12 +203,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
}
[Fact]
- public async Task RecordsProvenance_ForACalibratedLine()
+ public async Task RecordsMeasuredOffsetSeparatelyFromTheAppliedOne()
{
- // P8: what the writer wrote, what we subtracted, and how we knew — the evidence that
- // makes a stored timestamp recomputable without the diagnostics archive.
+ // The regression that forced the revert shipped an event tagged "calibrated" while
+ // carrying an offset that did not hold for that line. Measured and applied are now
+ // separate fields so a future reader cannot mistake one for the other.
using var h = new Harness();
- var writerOffset = TimeSpan.FromHours(-7); // PST/PDT, the OOBE default
+ var writerOffset = TimeSpan.FromHours(-7); // PDT, the OOBE default
h.Append(Line("marker 1", h.Now, writerOffset));
await h.Pass();
@@ -219,18 +219,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
await h.Pass();
h.Now = T0.AddSeconds(20);
- var writtenAt = h.Now;
- h.Append(Line("marker 3", writtenAt, writerOffset));
+ h.Append(Line("marker 3", h.Now, writerOffset));
await h.Pass();
- Assert.Equal(CmTraceOffsetOrigin.Calibrated, h.Tracker.LastMatchedSourceOffsetOrigin);
- Assert.Equal(-420, h.Tracker.LastMatchedSourceOffsetMinutes);
- Assert.True(h.Tracker.LastMatchedSourceLocalTimestamp.HasValue);
+ // Measured: the writer's actual belief.
+ Assert.Equal(-420, h.Tracker.LastMatchedMeasuredWriterOffsetMinutes);
- // 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);
+ // Applied: still the reader zone, and reported as such — never as "calibrated".
+ Assert.NotEqual(CmTraceOffsetOrigin.Calibrated, h.Tracker.LastMatchedSourceOffsetOrigin);
}
[Fact]
@@ -244,8 +240,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
await h.Pass();
Assert.Equal(CmTraceOffsetOrigin.None, h.Tracker.LastMatchedSourceOffsetOrigin);
- Assert.Null(h.Tracker.LastMatchedSourceOffsetMinutes);
Assert.True(h.Tracker.LastMatchedSourceLocalTimestamp.HasValue);
+
+ // The APPLIED offset is reported even on the fallback path — an event that states no
+ // offset at all cannot be recomputed later, which defeats the purpose of recording
+ // provenance. Asserted against the running machine's zone so this stays portable.
+ var readerZone = (int)TimeZoneInfo.Local
+ .GetUtcOffset(h.Tracker.LastMatchedSourceLocalTimestamp!.Value).TotalMinutes;
+ Assert.Equal(readerZone, h.Tracker.LastMatchedSourceOffsetMinutes);
}
[Fact]
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 d2f4404c..122729cf 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
@@ -254,6 +254,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
LastMatchedSourceLocalTimestamp = null;
LastMatchedSourceOffsetMinutes = null;
LastMatchedSourceOffsetOrigin = CmTraceOffsetOrigin.None;
+ LastMatchedMeasuredWriterOffsetMinutes = null;
}
else
{
@@ -263,6 +264,15 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
LastMatchedSourceLocalTimestamp = entry.HasTimestamp ? entry.LocalTimestamp : (DateTime?)null;
LastMatchedSourceOffsetMinutes = offsetMinutes;
LastMatchedSourceOffsetOrigin = origin;
+
+ // Observational: what the calibrator measured for this file, distinct from what
+ // was applied above.
+ TimeSpan measuredWriterOffset;
+ LastMatchedMeasuredWriterOffsetMinutes =
+ _currentSourceFileName != null
+ && OffsetCalibrator.TryGetOffset(_currentSourceFileName, out measuredWriterOffset)
+ ? (int)measuredWriterOffset.TotalMinutes
+ : (int?)null;
}
// Generic pattern-match hook (M4.4.4). Invoked before action-specific callbacks so
@@ -640,21 +650,25 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
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. Origin stays None so the emitted event says so.
+ // REVERTED 2026-08-20 (session e9753578): the measured offset is NOT applied.
+ //
+ // Calibration keeps one offset per FILE, but a single log file can hold lines from
+ // two writer eras — IME restarting across a timezone change leaves older lines in the
+ // old zone and newer ones in the new zone, in the same file. The anchor is the newest
+ // line, so its offset was also applied to the older lines, for which it is wrong. In
+ // the field that shifted 5 script_started events by -9 h while their script_completed
+ // counterparts were resolved correctly, inflating every script duration to ~32,400 s.
+ //
+ // The deeper lesson: applying the reader zone uniformly is wrong for ABSOLUTE times
+ // but self-consistent for DERIVED ones — both ends of a duration are wrong by the same
+ // amount, so the duration is right. Correcting only some timestamps produced a mixed
+ // frame INSIDE one session, which is strictly worse. Until the calibrator is era-aware
+ // (see tasks/todo.md), uniform beats partially-correct.
+ //
+ // The measurement itself still runs: it costs nothing, feeds the Info log and the
+ // event provenance, and is the field data the era-aware fix will be built on.
+ var readerZoneOffset = TimeZoneInfo.Local.GetUtcOffset(entry.LocalTimestamp);
+ offsetMinutes = (int)readerZoneOffset.TotalMinutes;
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 3064ec52..8859d4ac 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
@@ -228,6 +228,19 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
/// How that offset was arrived at — declared, measured, or neither.
public CmTraceOffsetOrigin LastMatchedSourceOffsetOrigin { get; internal set; }
+ ///
+ /// The offset the calibrator MEASURED for the source file, which is not necessarily the
+ /// one applied.
+ ///
+ /// Since the 2026-08-20 revert the measurement is observational only: it is recorded so the
+ /// field tells us what an era-aware calibrator would have to work with, without acting on
+ /// it. Reported separately from precisely so
+ /// the two can never be confused — that event said "calibrated" while carrying a wrong
+ /// value, and an honest record has to distinguish measured from applied.
+ ///
+ ///
+ public int? LastMatchedMeasuredWriterOffsetMinutes { get; internal set; }
+
// Callbacks to EnrollmentTracker
public Action OnEspPhaseChanged { get; set; }
public Action OnImeAgentVersion { get; set; }
diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs
index 7c6df6b8..e71360b8 100644
--- a/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs
+++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs
@@ -407,6 +407,13 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
var offsetMinutes = _tracker.LastMatchedSourceOffsetMinutes;
if (offsetMinutes.HasValue)
data["sourceOffsetMinutes"] = offsetMinutes.Value.ToString(culture);
+
+ // Observational only — what the calibrator measured, which since the 2026-08-20
+ // revert is deliberately NOT what was applied. Kept separate so the two can never
+ // be read as the same thing.
+ var measured = _tracker.LastMatchedMeasuredWriterOffsetMinutes;
+ if (measured.HasValue)
+ data["measuredWriterOffsetMinutes"] = measured.Value.ToString(culture);
}
if (!derivedFromClock) return;
@@ -421,6 +428,8 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
{
case CmTraceOffsetOrigin.Bias: return "bias";
case CmTraceOffsetOrigin.Calibrated: return "calibrated";
+ // Unreachable since the 2026-08-20 revert; kept so the vocabulary survives the
+ // era-aware fix rather than being reinvented.
// The writer's offset was never measured, so this process's own zone was assumed —
// correct only if the writer happens to share it.
default: return "reader-zone-fallback";