From 6f7ececa1f1a51a3f6b439e0dfd93f2e954afde4 Mon Sep 17 00:00:00 2001 From: Oliver Kieselbach Date: Sun, 4 Oct 2026 14:36:39 +0200 Subject: [PATCH] Platform scripts no longer take another executor's output and exit code: a cut line in AgentExecutor.log ends the invocation in front of it (D-317) Two AgentExecutor processes that open the log at the same end write their start blocks over each other. The end block of the one whose start block lost then sat behind the other executor's start block, and position-based ownership handed a Win32 detection script's stdout and exit code to the platform script. An AgentExecutor.log entry that is not exactly one CMTrace record (a fragment, a merged line or an empty line) is where one writer's bytes end and another's begin: it now closes the platform invocation in front of it and is never matched. Invocation markers live as long as the bytes of their entry: a rewind sets them aside and gives an entry that reads unchanged its markers back. Co-Authored-By: Claude Opus 5.5 (1M context) --- ...ckerOverwriteRewindTests.WriterBoundary.cs | 361 ++++++++++++++++++ .../Ime/ImeLogTrackerOverwriteRewindTests.cs | 4 +- .../Enrollment/Ime/ImeLogTracker.Handlers.cs | 8 +- .../Ime/ImeLogTracker.LogProcessing.cs | 30 +- .../Enrollment/Ime/ImeLogTracker.Overwrite.cs | 205 ++++++++-- 5 files changed, 566 insertions(+), 42 deletions(-) create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerOverwriteRewindTests.WriterBoundary.cs 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;