bump pointer: internal (D-319, concept docs, plan rewound-line-freshness, B-bmk)

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>

src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerOverwriteRewindTests.RewindFreshness.cs

@@ -0,0 +1,139 @@
+using System;
+using System.IO;
+using System.Linq;
+using System.Text;
+using System.Threading.Tasks;
+using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime;
+using AutopilotMonitor.Agent.V2.Core.SignalAdapters;
+using Xunit;
+
+namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
+{
+    /// <summary>
+    /// Sessions d29e27e3 and 4377911b: a concurrent IME writer overwrote the result line of a platform script, and the
+    /// overwrite check recovered it one pass later. Recovered lines were never fresh, so they resolved in the agent's own
+    /// cached zone (+60) instead of anchoring themselves (+120): the end stamp landed an hour ahead of the clock and the
+    /// run duration was omitted. Bytes that read differently at a position than at the last look were written after that
+    /// look, so when the replaced bytes were confirmed seconds ago the new line's age is bounded like an appended line's —
+    /// these tests pin that it anchors itself then, and only then.
+    /// </summary>
+    public sealed partial class ImeLogTrackerOverwriteRewindTests
+    {
+        private static void AppendExecutorLog(Harness h, string text)
+            => File.AppendAllText(Path.Combine(Path.GetDirectoryName(h.LogPath)!, "AgentExecutor.log"), text, new UTF8Encoding(false));
+
+        /// <summary>An IME log entry with the byte length of <paramref name="sameLengthAs"/>: what a stale writer's line replaces exactly.</summary>
+        private static string FillerLike(string time, string sameLengthAs)
+        {
+            var bare = ImeEntryAt(time, "[Win32App] checking ");
+            Assert.True(sameLengthAs.Length > bare.Length);
+            return ImeEntryAt(time, "[Win32App] checking " + new string('x', sameLengthAs.Length - bare.Length));
+        }
+
+        /// <summary>
+        /// A platform run whose IME writer lives in +120 (local = UTC + 2 h; the harness clock is 19:30Z): both logs are
+        /// observed empty first, so what follows is read fresh. Returns the IME log position where the filler line sits.
+        /// </summary>
+        private static async Task<long> StartRunAndReadFiller(Harness h, string fillerTime, string resultEntry)
+        {
+            h.Append(string.Empty);
+            AppendExecutorLog(h, string.Empty);
+            await h.Tracker.RunPollPassAsync(default);
+
+            AppendExecutorLog(h, RunStart("21:29:50.0000000", "1001"));
+            h.Append(ImeRunStart("21:29:48.0000000"));
+            await h.Tracker.RunPollPassAsync(default);
+
+            // Another IME writer appends a line; the tracker reads it.
+            var at = h.Length;
+            h.Append(FillerLike(fillerTime, resultEntry));
+            h.Now = h.Now.AddSeconds(1);
+            await h.Tracker.RunPollPassAsync(default);
+            return at;
+        }
+
+        [Fact]
+        public async Task Result_line_recovered_seconds_after_its_bytes_were_read_anchors_itself_like_a_fresh_line()
+        {
+            using var h = new Harness("IntuneManagementExtension.log", ScriptPatterns());
+            var result = ImeRunResult("21:30:01.1000000", "Success");
+            var at = await StartRunAndReadFiller(h, "21:30:00.5000000", result);
+
+            // The script ends: its end block, then the stale IME service writes the result over the filler.
+            AppendExecutorLog(h, RunEnd("21:30:01.0000000", 0, "done", ""));
+            h.Overwrite(at, result);
+            h.Now = h.Now.AddSeconds(1);
+            await PassAndSettle(h);
+
+            Assert.Equal(1, h.Health.OverwriteRewinds);
+            var script = Assert.Single(h.Completed);
+            Assert.Equal(CmTraceOffsetOrigin.LineAnchored, script.ResultProvenance!.Origin);
+            Assert.Equal(120, script.ResultProvenance.OffsetMinutes);
+            Assert.Equal(ImeLogTrackerAdapter.DurationPairVerdict.Verified, ImeLogTrackerAdapter.JudgeDurationPair(
+                script.StartedAtProvenance, script.ResultProvenance, false, script.ResultObservedAtUtc!.Value - script.StartedAtUtc!.Value, out _));
+        }
+
+        [Fact]
+        public async Task Verification_passes_keep_the_replaced_bytes_current_for_a_script_that_runs_longer()
+        {
+            using var h = new Harness("IntuneManagementExtension.log", ScriptPatterns());
+            var result = ImeRunResult("21:30:41.1000000", "Success");
+            var at = await StartRunAndReadFiller(h, "21:30:00.5000000", result);
+
+            // The script runs 40 s; the cadence check verifies the ledger every 10 s while the run is in flight.
+            for (var i = 0; i < 4; i++)
+            {
+                h.Now = h.Now.AddSeconds(10);
+                await h.Tracker.RunPollPassAsync(default);
+            }
+
+            AppendExecutorLog(h, RunEnd("21:30:41.0000000", 0, "done", ""));
+            h.Overwrite(at, result);
+            h.Now = h.Now.AddSeconds(1);
+            await PassAndSettle(h);
+
+            var script = Assert.Single(h.Completed);
+            Assert.Equal(CmTraceOffsetOrigin.LineAnchored, script.ResultProvenance!.Origin);
+            Assert.Equal(120, script.ResultProvenance.OffsetMinutes);
+        }
+
+        [Fact]
+        public async Task Overwrite_does_not_move_the_files_measured_writer_offset()
+        {
+            using var h = new Harness("IntuneManagementExtension.log", ScriptPatterns());
+            var result = ImeRunResult("21:30:01.1000000", "Success");
+            var at = await StartRunAndReadFiller(h, "21:30:00.5000000", result);
+            Assert.True(h.Tracker.OffsetCalibrator.TryGetOffset("IntuneManagementExtension.log", out var before));
+
+            AppendExecutorLog(h, RunEnd("21:30:01.0000000", 0, "done", ""));
+            h.Overwrite(at, result);
+            h.Now = h.Now.AddSeconds(1);
+            await PassAndSettle(h);
+
+            Assert.True(h.Tracker.OffsetCalibrator.TryGetOffset("IntuneManagementExtension.log", out var after));
+            Assert.Equal(before, after);
+        }
+
+        [Theory]
+        // Replaced bytes confirmed 1 s / 30 s ago: written since, age bounded like an appended line's.
+        [InlineData(true, true, 1, true)]
+        [InlineData(true, true, 30, true)]
+        // Confirmed longer ago: the new bytes could be minutes old — their age may round onto the 15-minute grid.
+        [InlineData(true, true, 31, false)]
+        // The clock stepped back since the confirmation: the age is unknown.
+        [InlineData(true, true, -1, false)]
+        // The divergence lies in bytes the ledger never held (dropped by a cap): nothing dates them.
+        [InlineData(true, false, 1, false)]
+        // The pass itself is not fresh — the first pass after a restart never anchors.
+        [InlineData(false, true, 1, false)]
+        // Nothing was replaced.
+        [InlineData(true, true, null, false)]
+        public void Rewound_entry_is_fresh_only_when_the_bytes_it_replaced_were_confirmed_within_the_fresh_window(
+            bool passLinesAreFresh, bool entryAtRewindPointReplaced, int? secondsSinceConfirmed, bool expected)
+        {
+            var now = new DateTime(2026, 10, 4, 19, 2, 0, DateTimeKind.Utc);
+            DateTime? confirmed = secondsSinceConfirmed.HasValue ? now.AddSeconds(-secondsSinceConfirmed.Value) : (DateTime?)null;
+            Assert.Equal(expected, ImeLogTracker.RewoundEntryIsFresh(passLinesAreFresh, entryAtRewindPointReplaced, confirmed, now));
+        }
+    }
+}

src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerOverwriteRewindTests.cs

@@ -502,6 +502,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
         public async Task Ime_result_line_hidden_by_an_executor_start_line_is_recovered_from_the_ime_log()
         {
             using var h = new Harness("IntuneManagementExtension.log", ScriptPatterns());
+            // Seen empty first: the start lines are fresh and anchor themselves like the recovered result line will,
+            // so start and result sit on one timeline whatever the host's own zone is.
+            h.Append(string.Empty);
+            await h.Pass();
             h.Append(Entry(GeneratedLine, "17") + Entry("Launch powershell executor in user session", "17") + Entry("process id = 10608", "17"));
             await h.Pass();
             var servicePosition = h.Length;

src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.LogProcessing.cs

@@ -123,8 +123,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
             var ledger = IsMultiWriterLogFile(fileName) ? GetLedger(fileName) : null;
 
             // Set by a rewind: entries that still read unchanged behind the old bookmark are
-            // skipped (their invocation markers are given back), and nothing below the old
-            // bookmark is fresh or a calibration anchor.
+            // skipped (their invocation markers are given back); a changed entry below the old
+            // bookmark is fresh only when the bytes it replaced were seen moments ago, and never a
+            // calibration anchor.
             RewindState rewind = null;
             long oldBookmark = -1;
             var writerBoundaries = IsWriterBoundaryLogFile(fileName);
@@ -171,12 +172,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
                     var guardFrom = ledger.OffsetOfEntryAtOrAfter(startPos - OverwriteGuardBytes);
                     if (guardFrom >= 0 && guardFrom < startPos)
                     {
-                        var divergence = await FindOverwriteAsync(stream, ledger, guardFrom, startPos, token);
+                        var divergence = await FindOverwriteAsync(stream, ledger, guardFrom, startPos, passNowUtc, token);
                         _verifiedBytes += startPos - guardFrom;
                         if (divergence >= 0)
                         {
                             // The guard saw only the tail of the ledger; the block may start earlier.
-                            var earliest = await FindOverwriteAsync(stream, ledger, ledger.StartOffset, startPos, token);
+                            var earliest = await FindOverwriteAsync(stream, ledger, ledger.StartOffset, startPos, passNowUtc, token);
                             _verifiedBytes += startPos - ledger.StartOffset;
                             _verifyPasses++;
                             if (earliest >= 0) divergence = earliest;
@@ -271,7 +272,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
                         }
                     }
 
-                    if (ledger != null) ledger.Record(entry);
+                    if (ledger != null) ledger.Record(entry, passNowUtc);
                     var unchanged = rewind != null && rewind.IsUnchanged(entry);
                     if (unchanged) RestoreInvocationMarkers(rewind, entry.Offset);
 
@@ -287,7 +288,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
 
                     if (unchanged) continue; // unchanged behind the old bookmark — processed before the rewind
 
-                    _currentPassLinesAreFresh = passLinesAreFresh && entry.Offset >= oldBookmark;
+                    // Behind the old bookmark only changed entries arrive here: fresh when the bytes they replaced
+                    // were seen moments ago (RewoundEntryIsFresh), never a calibration anchor.
+                    _currentPassLinesAreFresh = entry.Offset >= oldBookmark
+                        ? passLinesAreFresh
+                        : rewind != null && RewoundEntryIsFresh(passLinesAreFresh, rewind.EntryAtRewindPointReplaced, rewind.OldestReplacedSeenUtc, passNowUtc);
 
                     // --- Normal processing (single-line or completed multiline) ---
                     CmTraceLogEntry parsed;

src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Overwrite.cs

@@ -62,6 +62,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
             public long Offset;
             public int Length;
             public ulong Hash;
+            /// <summary>
+            /// When these bytes were last seen as they are (read, seeded or verified unchanged): bytes found different
+            /// at this position later were written after it. Not part of the identity.
+            /// </summary>
+            public DateTime SeenUtc;
 
             // Identity is (offset, hash): a tail first read unterminated and later completed
             // keeps its hash but grows by its terminator.
@@ -100,11 +105,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
                 return idx < Entries.Count ? Entries[idx].Offset : -1;
             }
 
-            public void Record(AssembledEntry e)
+            public void Record(AssembledEntry e, DateTime seenUtc)
             {
                 var idx = IndexOfFirstAtOrAfter(e.Offset);
                 if (idx < Entries.Count) Entries.RemoveRange(idx, Entries.Count - idx);
-                Entries.Add(new LedgerEntry { Offset = e.Offset, Length = e.Length, Hash = e.Hash });
+                Entries.Add(new LedgerEntry { Offset = e.Offset, Length = e.Length, Hash = e.Hash, SeenUtc = seenUtc });
             }
 
             /// <summary>Drops everything from <paramref name="offset"/> on and returns it — the entries a rewind must not process twice.</summary>
@@ -197,7 +202,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
             {
                 ledger.Seeded = true;
                 if (ledger.Entries.Count == 0 && bookmark > 0)
-                    await SeedLedgerAsync(filePath, ledger, bookmark, token).ConfigureAwait(false);
+                    await SeedLedgerAsync(filePath, ledger, bookmark, nowUtc, token).ConfigureAwait(false);
             }
 
             var due = ledger.VerifyRequested || (InContention(nowUtc) && nowUtc >= ledger.NextCadenceVerifyUtc);
@@ -213,7 +218,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
 
             long divergence;
             using (var stream = new FileStream(filePath, FileMode.Open, FileAccess.Read, FileShare.ReadWrite))
-                divergence = await FindOverwriteAsync(stream, ledger, from, bookmark, token).ConfigureAwait(false);
+                divergence = await FindOverwriteAsync(stream, ledger, from, bookmark, nowUtc, token).ConfigureAwait(false);
             if (token.IsCancellationRequested) return -1;
 
             ledger.VerifyRequested = false;
@@ -228,8 +233,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
         /// Re-reads [fromOffset, toOffset) with the read loop's assembler and compares against the
         /// ledger. Returns the offset of the first entry whose bytes changed — a ledger entry not
         /// reproduced, or an entry the ledger never had — or -1 when everything reads as before.
+        /// Every entry found unchanged is stamped seen at <paramref name="nowUtc"/>.
         /// </summary>
-        private async Task<long> FindOverwriteAsync(FileStream stream, FileLedger ledger, long fromOffset, long toOffset, CancellationToken token)
+        private async Task<long> FindOverwriteAsync(FileStream stream, FileLedger ledger, long fromOffset, long toOffset, DateTime nowUtc, CancellationToken token)
         {
             var entries = ledger.Entries;
             var idx = ledger.IndexOfFirstAtOrAfter(fromOffset);
@@ -255,6 +261,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
                 if (idx < entries.Count && entries[idx].Offset == e.Offset)
                 {
                     if (entries[idx].Hash != e.Hash) return e.Offset;
+                    var confirmed = entries[idx];
+                    confirmed.SeenUtc = nowUtc;
+                    entries[idx] = confirmed;
                     idx++;
                     continue;
                 }
@@ -265,7 +274,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
         }
 
         /// <summary>After a restart the ledger is empty: fingerprint the entries just behind the persisted bookmark without processing them.</summary>
-        private async Task SeedLedgerAsync(string filePath, FileLedger ledger, long bookmark, CancellationToken token)
+        private async Task SeedLedgerAsync(string filePath, FileLedger ledger, long bookmark, DateTime nowUtc, CancellationToken token)
         {
             var from = Math.Max(0, bookmark - RestartSeedBytes);
             using (var stream = new FileStream(filePath, FileMode.Open, FileAccess.Read, FileShare.ReadWrite))
@@ -288,7 +297,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
                     if (assembler.Feed(line, reader.LastLineStart, reader.Position, reader.LastLineTruncated, reader.LastLineHash, out e)
                             == CmTraceEntryAssembler.Outcome.Entry
                         && e.Offset + e.Length <= bookmark)
-                        ledger.Record(e);
+                        ledger.Record(e, nowUtc);
                 }
             }
         }
@@ -300,12 +309,17 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
         /// </summary>
         private sealed class RewindState
         {
-            public RewindState(string fileName, HashSet<LedgerEntry> unchanged, List<InvocationMarker> markers, InvocationMarker lastPlatformMarker)
+            public RewindState(string fileName, HashSet<LedgerEntry> unchanged, List<InvocationMarker> markers, InvocationMarker lastPlatformMarker, long rewindTo)
             {
                 FileName = fileName;
                 Unchanged = unchanged;
                 Markers = markers;
                 LastPlatformMarker = lastPlatformMarker;
+                foreach (var replaced in unchanged)
+                {
+                    if (replaced.Offset == rewindTo) EntryAtRewindPointReplaced = true;
+                    if (!OldestReplacedSeenUtc.HasValue || replaced.SeenUtc < OldestReplacedSeenUtc.Value) OldestReplacedSeenUtc = replaced.SeenUtc;
+                }
             }
 
             public string FileName { get; }
@@ -315,10 +329,29 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
             /// <summary>The tracker-wide last platform marker, when it was among the set-aside ones.</summary>
             public InvocationMarker LastPlatformMarker { get; }
             public int Next { get; set; }
+            /// <summary>The ledger held the entry at the rewind point: the changed bytes lie where something was seen before.</summary>
+            public bool EntryAtRewindPointReplaced { get; }
+            /// <summary>The earliest time any of the replaced bytes was last seen as it was: every changed byte was written after it.</summary>
+            public DateTime? OldestReplacedSeenUtc { get; }
 
             public bool IsUnchanged(AssembledEntry entry) => Unchanged.Contains(new LedgerEntry { Offset = entry.Offset, Hash = entry.Hash });
         }
 
+        /// <summary>
+        /// Whether an entry a rewind re-processes (it reads differently than before) is fresh. Its bytes were written after
+        /// the bytes it replaced were last seen as they were — IME stamps a line when it writes it — so when that was at
+        /// most <see cref="FreshLineMaxAge"/> ago the entry's age is bounded like an appended line's and it may anchor
+        /// itself (session d29e27e3: recovered result lines fell back to the agent's stale zone and lost their duration).
+        /// Not fresh when the pass is not (the first pass after a restart never anchors), when the divergence lies in bytes
+        /// the ledger never held (nothing dates them), or when the clock stepped back since.
+        /// </summary>
+        internal static bool RewoundEntryIsFresh(bool passLinesAreFresh, bool entryAtRewindPointReplaced, DateTime? oldestReplacedSeenUtc, DateTime passNowUtc)
+        {
+            if (!passLinesAreFresh || !entryAtRewindPointReplaced || !oldestReplacedSeenUtc.HasValue) return false;
+            var sinceSeen = passNowUtc - oldestReplacedSeenUtc.Value;
+            return sinceSeen >= TimeSpan.Zero && sinceSeen <= FreshLineMaxAge;
+        }
+
         /// <summary>Moves the bookmark back to the first changed entry; returns what the re-read needs to skip and to give back.</summary>
         private RewindState ApplyRewind(string filePath, string fileName, FileLedger ledger, long rewindTo, long bookmark)
         {
@@ -341,7 +374,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
             {
                 _logger.Debug(message);
             }
-            return new RewindState(fileName, removed, markers, tookLastPlatformMarker ? lastPlatformMarker : null);
+            return new RewindState(fileName, removed, markers, tookLastPlatformMarker ? lastPlatformMarker : null, rewindTo);
         }
 
         private long RetentionFloor(string fileName, long bookmark)