revert(agent): stop applying the measured CMTrace offset — one offset per file is wrong

Field regression, session e9753578 (agent 2.0.1410, PST-defaulted device in DE). Five script_started events resolved 9 h early while their script_completed counterparts resolved correctly, inflating every platform-script duration to ~32,400 s. Reverts the application introduced in e9dba11b. Root cause: calibration keeps ONE offset per log file, but a single 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 does not hold. The class doc even claimed "self-healing on writer restart" — that reasoning only ever covered FUTURE lines, never the ones already on disk. The more expensive mistake was the second one: correcting ABSOLUTE timestamps without checking what depends on their DIFFERENCES. Applying the reader zone uniformly is wrong in absolute terms but self-consistent — 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 than being uniformly wrong. This is the same asymmetry the original analysis described for AppInstallSummaries (68 min reported against 8 min real) and then reproduced. What stays, deliberately: - Bias-carrying lines still resolve via the writer-declared offset; that path was never implicated. - The measurement keeps running. It costs nothing, feeds the Info log, and is the field data the era-aware fix has to be built on — the first anlauf got the era question wrong from assumption rather than observation. - Provenance now separates measured from applied (measuredWriterOffsetMinutes vs sourceOffsetMinutes). The broken event was tagged "calibrated" while carrying an offset that did not hold for its line; that confusion must not be expressible. - The fallback path reports the offset it actually applied. An event stating no offset cannot be recomputed later, which defeats the point of provenance. Provenance earned its keep here: 57 events measured -420 (the PDT writer) against 5 at +120 made the diagnosis a two-minute query instead of median statistics over a session. Next: era-aware calibration keyed on the IME-STARTED marker, which we already track, plus a test over a log file containing two writer eras — the case that was missing. Agent 2393 green against a verified-clean build. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-10-25 21:19:38 +00:00 · 2026-08-20 14:31:50 +02:00
parent 3b59dab2df
commit 04b1a7c6e7
4 changed files with 86 additions and 48 deletions
@@ -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]
@@ -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);
        }

@@ -228,6 +228,19 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
        /// <summary>How that offset was arrived at — declared, measured, or neither.</summary>
        public CmTraceOffsetOrigin LastMatchedSourceOffsetOrigin { get; internal set; }

+        /// <summary>
+        /// The offset the calibrator MEASURED for the source file, which is not necessarily the
+        /// one applied.
+        /// <para>
+        /// 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 <see cref="LastMatchedSourceOffsetMinutes"/> 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.
+        /// </para>
+        /// </summary>
+        public int? LastMatchedMeasuredWriterOffsetMinutes { get; internal set; }
+
        // Callbacks to EnrollmentTracker
        public Action<string> OnEspPhaseChanged { get; set; }
        public Action<string> OnImeAgentVersion { get; set; }
@@ -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";