diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerOverwriteRewindTests.WriterBoundary.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerOverwriteRewindTests.WriterBoundary.cs new file mode 100644 index 00000000..a815f120 --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerOverwriteRewindTests.WriterBoundary.cs @@ -0,0 +1,361 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using System.Threading.Tasks; +using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime; +using Xunit; + +namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime +{ + /// + /// Session 756970cf: IME launched a Win32 detection executor and a platform-script executor 15 ms apart, and both + /// opened AgentExecutor.log at the same end-of-file offset. The platform executor's shorter start block overwrote + /// the detection executor's, whose identity line the tracker never saw; the detection's end block (exit 1 and its + /// stdout), written at its own position behind its own start block, then sat behind the PLATFORM start block, and + /// "the nearest preceding marker owns the line" handed another script's output and exit code to the platform + /// script. These tests pin the writer boundary: an entry that is not exactly one CMTrace record is where one + /// writer's bytes end and another's begin, and nothing behind it belongs to the invocation in front of it. + /// + public sealed partial class ImeLogTrackerOverwriteRewindTests + { + private const string RaceUserId = "00000000-0000-0000-0000-000000000000"; + private const string RacePlatformId = "1d6f0a52-3c4e-4b7a-9e21-5f8c7d2b9a10"; + private const string RaceDetectionAppId = "8b2e4c71-6a9d-4f03-b5e8-2c7a1d9f4e36"; + private const string RaceFillerAppId = "5e1c2b7d-0a4f-4c8e-9d36-7b2f1e8a4c50"; + private const string ImeDir = @"C:\Program Files (x86)\Microsoft Intune Management Extension"; + private const string DetectionStdout = "VERBOSE: === Sample Suite Detection Started ===\r\nWARNING: === DETECTION FAILED: Sample Suite is not installed ==="; + private const string PlatformStdout = "=== bootstrap loader started ===\r\nInstaller finished (exit code 0)."; + + private static string EntryAt(string time, string message) + => $"\r\n"; + + /// The four lines every AgentExecutor invocation starts with — identical length for every executor. + private static string ExecutorBanner(string time) + => EntryAt(time, "ExecutorLog AgentExecutor gets invoked") + + EntryAt(time, "Creating command line parser, name delimiter is - and value separator is .") + + EntryAt(time, "Getting Ordered Parameters") + + EntryAt(time, "Parsing Ordered Parameters."); + + private static string ExecutorLaunch(string time, string scriptPath, string pid) + => EntryAt(time, "Prepare to run Powershell Script ..") + + EntryAt(time, $"cmd line for running powershell is -NoProfile -executionPolicy bypass -file \"{scriptPath}\" ") + + EntryAt(time, "runAs32BitOn64 = False, so Disable Wow64FsRedirection") + + EntryAt(time, @"PowerShell path is C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe") + + EntryAt(time, $"[Executor] created powershell with process id {pid}"); + + private static string PlatformStartBlock(string time, string policyId, string pid) + { + var path = $@"{ImeDir}\Policies\Scripts\{RaceUserId}_{policyId}.ps1"; + var results = $@"{ImeDir}\Policies\Results\{RaceUserId}_{policyId}"; + return ExecutorBanner(time) + + EntryAt(time, $"Adding argument powershell with value {path} to the named argument list.") + + EntryAt(time, "Powershell option gets invoked") + + EntryAt(time, path) + + EntryAt(time, results + ".output") + + EntryAt(time, results + ".error") + + EntryAt(time, results + ".timeout") + + ExecutorLaunch(time, path, pid); + } + + private static string DetectionStartBlock(string time, string appId, string pid) + { + var path = $@"{ImeDir}\Content\DetectionScripts\{appId}_2.ps1"; + return ExecutorBanner(time) + + EntryAt(time, $"Adding argument powershellDetection with value {path} to the named argument list.") + + EntryAt(time, "PowershellDetection option gets invoked") + + EntryAt(time, path) + + EntryAt(time, path + "quotedResultFilePath.txt") + + EntryAt(time, path + "quotedErrorFilePath.txt") + + EntryAt(time, path + "quotedTimeoutFilePath.txt") + + EntryAt(time, path + "quotedExitCodeFilePath.txt") + + ExecutorLaunch(time, path, pid); + } + + private static string ExecutorEndBlock(string time, int exitCode, string stdout) + => EntryAt(time, $"Powershell exit code is {exitCode}") + + EntryAt(time, $"length of out={stdout.Length}") + + EntryAt(time, "length of error=0") + + EntryAt(time, "error from script =") + + EntryAt(time, exitCode == 0 ? "Powershell script is successfully executed." : "Powershell script is failed to execute") + + EntryAt(time, $"write output done. output = {stdout}, error = ") + + EntryAt(time, "Revert Wow64FsRedirection") + + EntryAt(time, "Agent executor completed."); + + private static string PlatformResultLine(string policyId) + => $"[PowerShell] User Id = {RaceUserId}, Policy id = {policyId}, policy result = Success"; + + /// The file offsets at which the entries of an ASCII start when it is written at . + private static HashSet EntryStarts(string block, long at) + { + Assert.True(block.All(c => c < 128), "offset arithmetic assumes ASCII test content"); + var starts = new HashSet(); + for (var i = block.IndexOf("= 0; i = block.IndexOf("= 1); + + // C ends: its end block lands at its own position, right behind its own (overwritten) start block. + Assert.Equal(x + cStart.Length, h.Length); + var cEnd = ExecutorEndBlock("12:00:07.0000000", 1, DetectionStdout); + h.Append(cEnd); + h.Now = h.Now.AddSeconds(6); + await h.Pass(); + + // IME's result for D reaches the tracker before D's own end block: the completion must wait for it. + h.Tracker.ProcessLogMessageForTest(PlatformResultLine(RacePlatformId), sourceFileName: "IntuneManagementExtension.log"); + Assert.Empty(h.Completed); + + // D ends: its end block lands at ITS position, over the fragment and C's bytes; C's last line survives. + var dEnd = ExecutorEndBlock("12:00:09.5000000", 0, PlatformStdout); + Assert.True(dEnd.Length < cStart.Length - dStart.Length + cEnd.Length); + h.Overwrite(x + dStart.Length, dEnd); + h.Now = h.Now.AddMilliseconds(130); + await h.Pass(); + h.Tracker.FlushPendingPlatformScriptResults(h.Now); + + var script = Assert.Single(h.Completed); + Assert.Equal(RacePlatformId, script.PolicyId); + Assert.Equal("Success", script.Result); + Assert.Equal(0, script.ExitCode); + Assert.Equal(PlatformStdout.Replace("\r\n", "\n"), script.Stdout); + Assert.DoesNotContain(h.Completed, s => (s.Stdout ?? string.Empty).Contains("Detection")); + } + + /// + /// The mirror image: a foreign executor whose stream position lies inside the platform start block (it opened + /// at the same end with a shorter start block) writes its end block there. Its first line merges with the head of + /// a platform line — cut inside the message or inside the trailer, which the parser would otherwise read up to + /// the foreign trailer — and its output line follows without any marker in between. + /// + [Theory] + [InlineData(15)] + [InlineData(-30)] + public async Task Foreign_end_block_merged_into_the_platform_start_block_never_reaches_the_platform_script(int cut) + { + using var h = new Harness("AgentExecutor.log", ScriptPatterns()); + h.Append(DetectionStartBlock("12:00:00.0000000", RaceFillerAppId, "1548") + ExecutorEndBlock("12:00:00.5000000", 0, "detected")); + await h.Pass(); + var x = h.Length; + + var dStart = PlatformStartBlock("12:00:01.0000000", RacePlatformId, "2524"); + h.Append(dStart); + await h.Pass(); + + // The foreign end block starts inside the line after D's argument line. + var lineAfterArgument = x + dStart.IndexOf(" 0 ? cut : lineLength + cut); + var foreignEnd = ExecutorEndBlock("12:00:03.0000000", 1, "foreign output"); + Assert.True(at + foreignEnd.Length < x + dStart.Length, "the foreign block must end inside D's start block"); + h.Overwrite(at, foreignEnd); + h.Tracker.RequestOverwriteCheckForTest(); + h.Now = h.Now.AddMilliseconds(100); + await h.Pass(); + + h.Tracker.ProcessLogMessageForTest(PlatformResultLine(RacePlatformId), sourceFileName: "IntuneManagementExtension.log"); + h.Now = h.Now.Add(ImeLogTracker.PlatformScriptEndBlockGrace); + h.Tracker.FlushPendingPlatformScriptResults(h.Now); + + // No owner is provable behind the cut: the completion goes out without end-block data, never with the foreign one. + var script = Assert.Single(h.Completed); + Assert.Equal("Success", script.Result); + Assert.Null(script.ExitCode); + Assert.Null(script.Stdout); + } + + [Fact] + public async Task Entry_read_unchanged_after_a_rewind_keeps_its_platform_marker() + { + const string platformId = "2b7d9e41-8c3a-4f60-a5d2-9e1b7c4f3a08"; + using var h = new Harness("AgentExecutor.log", ScriptPatterns()); + + // Detection W waits for its script; detection X runs completely behind it; platform F starts behind X. + var wStart = DetectionStartBlock("12:00:00.0000000", RaceFillerAppId, "1111"); + var xRun = DetectionStartBlock("12:00:00.2000000", RaceDetectionAppId, "2222") + ExecutorEndBlock("12:00:00.4000000", 0, "x detected"); + h.Append(wStart + xRun + PlatformStartBlock("12:00:01.0000000", platformId, "3333")); + await h.Pass(); + + // W ends at its own position, over the head of X's run; F's start block keeps its bytes and offset. + var wEnd = ExecutorEndBlock("12:00:02.0000000", 0, "w detected"); + Assert.True(wEnd.Length < xRun.Length); + h.Overwrite(wStart.Length, wEnd); + h.Tracker.RequestOverwriteCheckForTest(); + h.Now = h.Now.AddMilliseconds(100); + await h.Pass(); + Assert.Equal(1, h.Health.OverwriteRewinds); + + // F's end block lands behind its start block: still F's, because F's marker survived with its bytes. + h.Append(ExecutorEndBlock("12:00:05.0000000", 7, "Hello from F")); + h.Now = h.Now.AddMilliseconds(100); + await h.Pass(); + h.Tracker.ProcessLogMessageForTest(PlatformResultLine(platformId), sourceFileName: "IntuneManagementExtension.log"); + + var script = Assert.Single(h.Completed); + Assert.Equal(platformId, script.PolicyId); + Assert.Equal(7, script.ExitCode); + Assert.Equal("Hello from F", script.Stdout); + } + + [Fact] + public async Task Writer_boundary_read_unchanged_after_a_rewind_still_closes_the_platform_invocation() + { + using var h = new Harness("AgentExecutor.log", ScriptPatterns()); + + // Detection Q waits for its script while detection R runs completely behind it. + var qStart = DetectionStartBlock("12:00:00.0000000", RaceFillerAppId, "1111"); + var rRun = DetectionStartBlock("12:00:00.2000000", "6c3f8a20-1d5e-4b97-8f4a-0e2d6b9c7a13", "2222") + ExecutorEndBlock("12:00:00.4000000", 0, "r detected"); + h.Append(qStart + rRun); + await h.Pass(); + var x = h.Length; + + // The race of the field case behind them: the boundary closes D. + var cStart = DetectionStartBlock("12:00:01.0000000", RaceDetectionAppId, "6416"); + var dStart = PlatformStartBlock("12:00:01.2000000", RacePlatformId, "2524"); + h.Append(cStart); + h.Overwrite(x, dStart); + h.Now = h.Now.AddMilliseconds(100); + await h.Pass(); + + // Q ends at its own position, over R's run: the rewind starts in front of the race, whose bytes read unchanged. + var qEnd = ExecutorEndBlock("12:00:02.0000000", 0, "q detected"); + Assert.True(qEnd.Length < rRun.Length); + h.Overwrite(qStart.Length, qEnd); + h.Tracker.RequestOverwriteCheckForTest(); + h.Now = h.Now.AddMilliseconds(100); + await h.Pass(); + + // C's end block behind the boundary stays unowned; D's own end block completes D. + var cEnd = ExecutorEndBlock("12:00:07.0000000", 1, DetectionStdout); + h.Append(cEnd); + h.Now = h.Now.AddMilliseconds(100); + await h.Pass(); + h.Tracker.ProcessLogMessageForTest(PlatformResultLine(RacePlatformId), sourceFileName: "IntuneManagementExtension.log"); + Assert.Empty(h.Completed); + + h.Overwrite(x + dStart.Length, ExecutorEndBlock("12:00:09.5000000", 0, PlatformStdout)); + h.Now = h.Now.AddMilliseconds(130); + await h.Pass(); + h.Tracker.FlushPendingPlatformScriptResults(h.Now); + + var script = Assert.Single(h.Completed); + Assert.Equal(0, script.ExitCode); + Assert.Equal(PlatformStdout.Replace("\r\n", "\n"), script.Stdout); + } + + [Fact] + public async Task Raw_text_in_the_executor_log_is_never_matched_and_closes_the_platform_invocation() + { + using var h = new Harness("AgentExecutor.log", ScriptPatterns()); + h.Append(PlatformStartBlock("12:00:00.0000000", RacePlatformId, "2524")); + await h.Pass(); + + // The tail of a cut line that happens to read like an exit line, then a foreign end block. + h.Append("Powershell exit code is 5\r\n" + ExecutorEndBlock("12:00:02.0000000", 6, "foreign output")); + // A fragment right at the bookmark stops the first pass for a check; the second one reads it. + h.Now = h.Now.AddMilliseconds(100); + await h.Pass(); + h.Now = h.Now.AddMilliseconds(100); + await h.Pass(); + + h.Tracker.ProcessLogMessageForTest(PlatformResultLine(RacePlatformId), sourceFileName: "IntuneManagementExtension.log"); + h.Now = h.Now.Add(ImeLogTracker.PlatformScriptEndBlockGrace); + h.Tracker.FlushPendingPlatformScriptResults(h.Now); + + var script = Assert.Single(h.Completed); + Assert.Null(script.ExitCode); + Assert.Null(script.Stdout); + } + + [Fact] + public async Task Fragment_in_the_ime_log_does_not_close_the_platform_run_context() + { + using var h = new Harness("IntuneManagementExtension.log", ScriptPatterns()); + // In the IME log the service writes the platform marker and the context line itself; the fragment in + // between is the tail of an executor's telemetry line and separates nothing. + h.Append(Entry(@"Script file C:\Program Files (x86)\Microsoft Intune Management Extension\Policies\Scripts\" + RaceUserId + "_" + RacePlatformId + ".ps1 is generated.", "17") + + "ing mananger...]LOG]!>\r\n" + + Entry("Launch powershell executor in user session", "17")); + await h.Pass(); + + h.Tracker.ProcessLogMessageForTest(PlatformResultLine(RacePlatformId)); + h.Now = h.Now.Add(ImeLogTracker.PlatformScriptEndBlockGrace); + h.Tracker.FlushPendingPlatformScriptResults(h.Now); + + var script = Assert.Single(h.Completed); + Assert.Equal("User", script.RunContext); + } + + [Fact] + public async Task Cut_multi_line_output_adds_one_boundary_not_one_per_line() + { + using var h = new Harness("AgentExecutor.log", ScriptPatterns()); + h.Append(PlatformStartBlock("12:00:00.0000000", RacePlatformId, "2524")); + await h.Pass(); + var markersBefore = h.Tracker.InvocationMarkerCountForTest("AgentExecutor.log"); + + var lines = string.Concat(Enumerable.Range(1, 600).Select(i => $"orphaned output line {i}\r\n")); + h.Append(lines); + h.Now = h.Now.AddMilliseconds(100); + await h.Pass(); + h.Now = h.Now.AddMilliseconds(100); + await h.Pass(); + + Assert.Equal(markersBefore + 1, h.Tracker.InvocationMarkerCountForTest("AgentExecutor.log")); + } + + [Theory] + [InlineData("", true)] + [InlineData("", true)] + [InlineData("\uFEFF", true)] + [InlineData("t code is 3]LOG]!>", false)] + [InlineData("", false)] + [InlineData("", false)] + [InlineData("", false)] + [InlineData("", false)] + public void Single_cmtrace_record_is_told_apart_from_the_cut_of_two_writers(string text, bool expected) + { + Assert.Equal(expected, ImeLogTracker.IsSingleCmTraceRecord(text)); + } + + [Theory] + [InlineData("AgentExecutor.log", true)] + [InlineData("AgentExecutor-20261003-233348.log", true)] + [InlineData("IntuneManagementExtension.log", false)] + [InlineData("IntuneManagementExtension-20261003-233348.log", false)] + [InlineData("HealthScripts.log", false)] + [InlineData("AppWorkload.log", false)] + public void Writer_boundaries_apply_to_the_executor_log_live_and_rotated(string fileName, bool expected) + { + Assert.Equal(expected, ImeLogTracker.IsWriterBoundaryLogFile(fileName)); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerOverwriteRewindTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerOverwriteRewindTests.cs index 2e431067..585eb830 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerOverwriteRewindTests.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerOverwriteRewindTests.cs @@ -25,7 +25,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime /// contract: unchanged bytes never rewind, changed bytes are processed exactly once, and the /// executor lines a rewind uncovers belong to the invocation that owns their file position. /// - public sealed class ImeLogTrackerOverwriteRewindTests + public sealed partial class ImeLogTrackerOverwriteRewindTests { private static readonly DateTime T0 = new DateTime(2026, 9, 10, 19, 30, 0, DateTimeKind.Utc); @@ -42,7 +42,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime private static readonly string[] ScriptPatternIds = { "PS-AGENT-INVOCATION", "PS-AGENT-ARG", "PS-AGENT-SCRIPT-START", "PS-AGENT-EXITCODE", - "PS-AGENT-OUTPUT", "PS-AGENT-COMPLETED", "PS-SCRIPT-GENERATED", "PS-SCRIPT-CONTEXT", "PS-SCRIPT-RESULT", + "PS-AGENT-OUTPUT", "PS-AGENT-ERROR", "PS-AGENT-COMPLETED", "PS-SCRIPT-GENERATED", "PS-SCRIPT-CONTEXT", "PS-SCRIPT-RESULT", }; /// The shipped pattern JSON — the same source combine.js embeds — so the contract is the real one. diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs index 351b70b9..29fdb0ff 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs @@ -439,6 +439,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime ApplyExitCode(script, exitCode, LastMatchedLogTimestamp ?? UtcNowProvider(), CaptureLastMatchedProvenance()); else if (ownerPolicyId != null) _logger.Debug($"ImeLogTracker: exit code {exitCode} belongs to platform script {ownerPolicyId}, whose completion was already emitted — dropped"); + else + LogLineBehindWriterBoundary($"exit code {exitCode}"); // An exit code means the executor just wrote its end block and IME is about to // write the result — both land at a stale stream position when another process // appended meanwhile. Check the ledgers on the next pass. @@ -465,7 +467,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime { var outputType = parameters != null && parameters.TryGetValue("outputType", out var ot) ? ot : null; var script = GetCurrentScriptForLineUpdate(parameters); - if (script == null) return; + if (script == null) + { + LogLineBehindWriterBoundary($"script output ({outputType ?? "combined"})"); + return; + } // PS-AGENT-OUTPUT captures both stdout and stderr in one pattern var output = match.Groups["output"]?.Value; 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 ce7fe183..5740d40c 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 @@ -123,16 +123,18 @@ 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, and nothing below the old bookmark is fresh or a calibration anchor. - HashSet rewoundEntries = null; + // skipped (their invocation markers are given back), and nothing below the old + // bookmark is fresh or a calibration anchor. + RewindState rewind = null; long oldBookmark = -1; + var writerBoundaries = IsWriterBoundaryLogFile(fileName); if (ledger != null) { var rewindTo = await PrepareLedgerAsync(filePath, fileName, ledger, startPos, passNowUtc, token); if (rewindTo >= 0) { - rewoundEntries = ApplyRewind(filePath, fileName, ledger, rewindTo, startPos); + rewind = ApplyRewind(filePath, fileName, ledger, rewindTo, startPos); oldBookmark = startPos; startPos = rewindTo; } @@ -164,7 +166,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime { // Guard zone: the file grew and is open anyway — re-check the entries just behind // the bookmark, where a stale writer's block lands when it is short. - if (ledger != null && rewoundEntries == null && ledger.Entries.Count > 0) + if (ledger != null && rewind == null && ledger.Entries.Count > 0) { var guardFrom = ledger.OffsetOfEntryAtOrAfter(startPos - OverwriteGuardBytes); if (guardFrom >= 0 && guardFrom < startPos) @@ -178,7 +180,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime _verifiedBytes += startPos - ledger.StartOffset; _verifyPasses++; if (earliest >= 0) divergence = earliest; - rewoundEntries = ApplyRewind(filePath, fileName, ledger, divergence, startPos); + rewind = ApplyRewind(filePath, fileName, ledger, divergence, startPos); oldBookmark = startPos; startPos = divergence; } @@ -259,7 +261,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime // A fragment right at the bookmark of a multi-writer file (the previous // entry ended exactly here, this one does not open an entry) is the tail of // a block a stale writer laid over already-read bytes: verify before reading on. - if (ledger != null && rewoundEntries == null && entry.Offset == ledger.EndOffset + if (ledger != null && rewind == null && entry.Offset == ledger.EndOffset && ledger.LastFragmentOffset != entry.Offset && !entry.Text.StartsWith("= oldBookmark; diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Overwrite.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Overwrite.cs index ae053c76..f6ce8166 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Overwrite.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Overwrite.cs @@ -293,13 +293,40 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime } } - /// Moves the bookmark back to the first changed entry; returns the entries to skip if they still read unchanged behind it. - private HashSet ApplyRewind(string filePath, string fileName, FileLedger ledger, long rewindTo, long bookmark) + /// + /// What one rewind pass carries: the entries to skip if they still read unchanged behind the rewind point, and + /// the invocation markers set aside there until their entries prove unchanged. Pass-local by design — whatever + /// is not given back dies with the pass on every exit path. + /// + private sealed class RewindState + { + public RewindState(string fileName, HashSet unchanged, List markers, InvocationMarker lastPlatformMarker) + { + FileName = fileName; + Unchanged = unchanged; + Markers = markers; + LastPlatformMarker = lastPlatformMarker; + } + + public string FileName { get; } + public HashSet Unchanged { get; } + /// Set aside at the rewind, ascending by offset. + public List Markers { get; } + /// The tracker-wide last platform marker, when it was among the set-aside ones. + public InvocationMarker LastPlatformMarker { get; } + public int Next { get; set; } + + public bool IsUnchanged(AssembledEntry entry) => Unchanged.Contains(new LedgerEntry { Offset = entry.Offset, Hash = entry.Hash }); + } + + /// Moves the bookmark back to the first changed entry; returns what the re-read needs to skip and to give back. + private RewindState ApplyRewind(string filePath, string fileName, FileLedger ledger, long rewindTo, long bookmark) { var removed = ledger.TruncateFrom(rewindTo); _positionTracker.SetPosition(filePath, rewindTo); _heldTails.Remove(filePath); - InvalidateInvocationMarkersFrom(fileName, rewindTo); + var lastPlatformMarker = _lastPlatformMarker; + var markers = TakeInvocationMarkersFrom(fileName, rewindTo, out var tookLastPlatformMarker); _overwriteRewinds++; _overwriteBytesReprocessed += bookmark - rewindTo; @@ -314,7 +341,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime { _logger.Debug(message); } - return removed; + return new RewindState(fileName, removed, markers, tookLastPlatformMarker ? lastPlatformMarker : null); } private long RetentionFloor(string fileName, long bookmark) @@ -331,20 +358,35 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime // ----------------------------------------------------------------------- // // AgentExecutor.log carries "Powershell exit code is N" / "write output done" without a - // policy id. Their owner is decided by FILE POSITION, not by the order lines were read: - // an executor writes its end block at its own stream position, i.e. directly after its - // own start block in the final bytes, so the nearest preceding invocation marker names - // it — and stays right after a rewind re-reads that region. A marker is a platform start - // (policy id), some other invocation (detection, remediation, requirement: null) or a - // close ("gets invoked" banner, "Agent executor completed"). + // policy id. Their owner is decided by FILE POSITION: the nearest preceding marker — a + // platform start (policy id), some other invocation (detection, remediation, requirement: + // null), a close ("gets invoked" banner, "Agent executor completed") or a writer boundary. + // + // Every executor writes its lines contiguously from its own stream position, so its end + // block follows its own start block — but that start block may be gone. Two executors that + // open the file at the same end write their start blocks over each other, and the end block + // of the one that lost then sits behind the OTHER executor's start block (session 756970cf: + // a detection script's exit code and output on a platform script). Where one writer's bytes + // meet another's, the cut leaves an entry that is not exactly one CMTrace record — a + // fragment, a merged line or an empty line — unless the line boundaries of both writers + // coincide byte-exactly. That writer boundary closes the platform invocation in front of it. + // AgentExecutor.log only: in the IME log the service writes the markers and the lines they + // own itself, and its fragments are executor telemetry lines. + // + // A marker lives exactly as long as the bytes of its entry: a rewind sets the markers from + // the rewind point on aside, and an entry that reads unchanged gets its markers back. private sealed class InvocationMarker { public long Offset; public string PolicyId; public bool IsClose; + /// Set on a writer boundary: the platform invocation it closed. + public string ClosedPolicyId; } + private const string ExecutorLogFileName = "AgentExecutor.log"; + private readonly Dictionary> _invocationMarkers = new Dictionary>(StringComparer.OrdinalIgnoreCase); private InvocationMarker _lastPlatformMarker; @@ -354,22 +396,59 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime private readonly HashSet _platformMarkerFiles = new HashSet(StringComparer.OrdinalIgnoreCase); private long _testEntryOrdinal; - private void RecordInvocationMarker(string policyId, bool isClose) + /// + /// The executor log, live or rotated (AgentExecutor-yyyyMMdd-HHmmss.log): its invocations are one process + /// each, so a writer boundary ends an invocation — in the final bytes of a rotation as much as in the live file. + /// + internal static bool IsWriterBoundaryLogFile(string fileName) + => string.Equals(fileName, ExecutorLogFileName, StringComparison.OrdinalIgnoreCase) + || (fileName != null + && fileName.StartsWith("AgentExecutor-", StringComparison.OrdinalIgnoreCase) + && fileName.EndsWith(".log", StringComparison.OrdinalIgnoreCase)); + + /// + /// True when the entry is exactly one CMTrace record: it opens with <![LOG[ (culture-sensitive like + /// CmTraceLogParser.TryParseLine, so a BOM is ignorable) and holds no second one — the parser takes the + /// message up to the LAST trailer, so a line cut anywhere, its trailer included, would swallow the record + /// written over it. An empty entry is the terminator of a cut line. A script whose own output contains the + /// open tag loses that output line: the bytes cannot tell it from a merged line. + /// + internal static bool IsSingleCmTraceRecord(string text) + { + if (string.IsNullOrEmpty(text) || !text.StartsWith(LogOpenTag)) return false; + var first = text.IndexOf(LogOpenTag, StringComparison.Ordinal); + return first >= 0 && text.IndexOf(LogOpenTag, first + LogOpenTag.Length, StringComparison.Ordinal) < 0; + } + + private List GetOrCreateMarkerList(string file) { - if (_currentEntryOffset < 0) return; - var file = _currentSourceFileName ?? TestSourceFileName; List list; if (!_invocationMarkers.TryGetValue(file, out list)) { list = new List(); _invocationMarkers[file] = list; } + return list; + } + + private static void AppendInvocationMarker(List list, InvocationMarker marker) + { + if (list.Count >= MaxInvocationMarkersPerFile) list.RemoveAt(0); + list.Add(marker); + } + + private void RecordInvocationMarker(string policyId, bool isClose) + { + if (_currentEntryOffset < 0) return; + var file = _currentSourceFileName ?? TestSourceFileName; + var list = GetOrCreateMarkerList(file); if (list.Count > 0 && list[list.Count - 1].Offset == _currentEntryOffset) { // Two patterns on one line: the platform start outranks the generic argument line. + // A writer boundary is never upgraded. var last = list[list.Count - 1]; - if (!isClose && policyId != null) + if (!isClose && policyId != null && last.ClosedPolicyId == null) { last.PolicyId = policyId; last.IsClose = false; @@ -379,9 +458,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime return; } - if (list.Count >= MaxInvocationMarkersPerFile) list.RemoveAt(0); var marker = new InvocationMarker { Offset = _currentEntryOffset, PolicyId = policyId, IsClose = isClose }; - list.Add(marker); + AppendInvocationMarker(list, marker); if (!isClose && policyId != null) { _lastPlatformMarker = marker; @@ -390,21 +468,34 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime } /// - /// The pending platform script that owns the entry being processed, or null. - /// names the owning platform script even when its slot is - /// gone (completion already emitted); null when no platform invocation owns the entry. + /// An entry of at that is not exactly one CMTrace record: + /// the bytes behind it were written by another process than the bytes in front of it. Closes the platform + /// invocation that owns the position; records nothing when none is open there (a cut multi-line output yields + /// one fragment per line). Idempotent at the same offset. /// - private ScriptExecutionState ResolvePlatformScriptForCurrentEntry(out string ownerPolicyId) + private void CloseAtWriterBoundary(string fileName, long offset, string text) + { + var owner = FindOwningMarker(fileName, offset); + if (owner == null || owner.IsClose || owner.PolicyId == null) return; + + var list = GetOrCreateMarkerList(fileName); + if (list.Count > 0 && list[list.Count - 1].Offset >= offset) return; + AppendInvocationMarker(list, new InvocationMarker { Offset = offset, IsClose = true, ClosedPolicyId = owner.PolicyId }); + + var kind = string.IsNullOrEmpty(text) ? "empty line" : text.StartsWith(LogOpenTag) ? "merged line" : "fragment"; + _logger.Debug($"ImeLogTracker: writer boundary in {fileName} at offset {offset} ({kind}, {text?.Length ?? 0} chars) closes platform script {owner.PolicyId} (opened at {owner.Offset}) — the bytes behind it belong to another executor"); + } + + /// The marker that owns in , or null. + private InvocationMarker FindOwningMarker(string file, long offset) { - ownerPolicyId = null; - var file = _currentSourceFileName ?? TestSourceFileName; InvocationMarker marker = null; List list = null; - if (_currentEntryOffset >= 0 && _invocationMarkers.TryGetValue(file, out list)) + if (offset >= 0 && _invocationMarkers.TryGetValue(file, out list)) { for (var i = list.Count - 1; i >= 0; i--) { - if (list[i].Offset <= _currentEntryOffset) + if (list[i].Offset <= offset) { marker = list[i]; break; @@ -420,6 +511,18 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime // (session 24dc69d1: the health-script worker's exit line pre-filled a platform slot's // exit code, its launch line the slot's context). if (marker == null && (list == null || list.Count == 0) && _platformMarkerFiles.Contains(file)) marker = _lastPlatformMarker; + return marker; + } + + /// + /// The pending platform script that owns the entry being processed, or null. + /// names the owning platform script even when its slot is + /// gone (completion already emitted); null when no platform invocation owns the entry. + /// + private ScriptExecutionState ResolvePlatformScriptForCurrentEntry(out string ownerPolicyId) + { + ownerPolicyId = null; + var marker = FindOwningMarker(_currentSourceFileName ?? TestSourceFileName, _currentEntryOffset); if (marker == null || marker.IsClose || marker.PolicyId == null) return null; ownerPolicyId = marker.PolicyId; @@ -427,17 +530,32 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime return _pendingPlatformScripts.TryGetValue(marker.PolicyId, out state) ? state : null; } - private void InvalidateInvocationMarkersFrom(string fileName, long offset) + /// Debug trace for an executor line that a writer boundary kept away from a platform script. + private void LogLineBehindWriterBoundary(string what) { + var marker = FindOwningMarker(_currentSourceFileName ?? TestSourceFileName, _currentEntryOffset); + if (marker?.ClosedPolicyId == null) return; + _logger.Debug($"ImeLogTracker: {what} at offset {_currentEntryOffset} lies behind the writer boundary at {marker.Offset} that closed platform script {marker.ClosedPolicyId} — another executor's end block, not attributed"); + } + + /// Removes the markers from on and returns them in offset order. + private List TakeInvocationMarkersFrom(string fileName, long offset, out bool tookLastPlatformMarker) + { + tookLastPlatformMarker = false; + var taken = new List(); List list; - if (!_invocationMarkers.TryGetValue(fileName, out list) || list.Count == 0) return; - var removedLast = false; - for (var i = list.Count - 1; i >= 0 && list[i].Offset >= offset; i--) + if (!_invocationMarkers.TryGetValue(fileName, out list) || list.Count == 0) return taken; + + var from = list.Count; + while (from > 0 && list[from - 1].Offset >= offset) from--; + for (var i = from; i < list.Count; i++) { - if (ReferenceEquals(list[i], _lastPlatformMarker)) removedLast = true; - list.RemoveAt(i); + if (ReferenceEquals(list[i], _lastPlatformMarker)) tookLastPlatformMarker = true; + taken.Add(list[i]); } - if (removedLast) + list.RemoveRange(from, list.Count - from); + + if (tookLastPlatformMarker) { _lastPlatformMarker = null; for (var i = list.Count - 1; i >= 0; i--) @@ -449,6 +567,28 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime } } } + return taken; + } + + private void InvalidateInvocationMarkersFrom(string fileName, long offset) => TakeInvocationMarkersFrom(fileName, offset, out _); + + /// + /// An entry that reads unchanged after a rewind keeps its markers: gives back the set-aside markers at exactly + /// . Set-aside markers in front of it belonged to entries that changed and stay + /// gone with their bytes. + /// + private void RestoreInvocationMarkers(RewindState rewind, long entryOffset) + { + var markers = rewind.Markers; + while (rewind.Next < markers.Count && markers[rewind.Next].Offset < entryOffset) rewind.Next++; + while (rewind.Next < markers.Count && markers[rewind.Next].Offset == entryOffset) + { + var marker = markers[rewind.Next++]; + var list = GetOrCreateMarkerList(rewind.FileName); + if (list.Count > 0 && list[list.Count - 1].Offset >= marker.Offset) continue; + AppendInvocationMarker(list, marker); + if (ReferenceEquals(marker, rewind.LastPlatformMarker)) _lastPlatformMarker = marker; + } } private long OldestPendingScriptMarkerOffset(string fileName) @@ -474,6 +614,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime /// What a rollover of the file does to its invocation markers. internal void ClearInvocationMarkersForTest(string fileName) => InvalidateInvocationMarkersFrom(fileName, 0); + internal int InvocationMarkerCountForTest(string fileName) + => _invocationMarkers.TryGetValue(fileName, out var list) ? list.Count : 0; + internal int LedgerEntryCountForTest(string fileName) { FileLedger ledger;