From 015a71f3eec03e7d6d289fdc2fe6a8e3c587f68d Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 30 Mar 2026 20:31:39 +0000 Subject: [PATCH 1/2] Initial plan From c2ebb928705661ed52250b8d8e0358ee0d1361b8 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 30 Mar 2026 20:41:52 +0000 Subject: [PATCH 2/2] Fix Docker multiplexed stream handling in CollectLogs to eliminate garbage characters in PF_ConsoleLogs.txt MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The Docker API returns a multiplexed stream with 8-byte binary headers per frame when the container is not running with TTY. The previous code read this stream using StreamReader.ReadLine(), which treated the binary headers as text, producing garbled characters (e.g., ��������) in the log file. Added DemuxDockerStream method that properly parses the Docker multiplexed stream format by reading and stripping the 8-byte headers (stream type + padding + payload size) before extracting the UTF-8 payload content. Agent-Logs-Url: https://github.com/PlayFab/MpsAgent/sessions/3632fce0-9338-4fa3-a907-6ada665fc04c Co-authored-by: dgkanatsios <8256138+dgkanatsios@users.noreply.github.com> --- .../DockerContainerEngineTests.cs | 90 +++++++++++++++++++ .../Interfaces/DockerContainerEngine.cs | 75 +++++++++++++--- 2 files changed, 154 insertions(+), 11 deletions(-) diff --git a/VmAgent.Core.UnitTests/DockerContainerEngineTests.cs b/VmAgent.Core.UnitTests/DockerContainerEngineTests.cs index ac39665..72c2a69 100644 --- a/VmAgent.Core.UnitTests/DockerContainerEngineTests.cs +++ b/VmAgent.Core.UnitTests/DockerContainerEngineTests.cs @@ -10,8 +10,12 @@ using Microsoft.Azure.Gaming.AgentInterfaces; using Microsoft.Extensions.Logging.Abstractions; using Moq; +using System; using System.Collections.Generic; +using System.IO; using System.Runtime.InteropServices; +using System.Text; +using System.Threading.Tasks; namespace VmAgent.Core.UnitTests { @@ -172,5 +176,91 @@ public void GetGameWorkingDir_LinuxHost_ShouldReturnNull() Assert.IsNull(result); } + + [TestMethod] + [TestCategory("BVT")] + public async Task DemuxDockerStream_SingleStdoutFrame_ExtractsContent() + { + string logLine = "BASH=/bin/bash\n"; + byte[] payload = Encoding.UTF8.GetBytes(logLine); + byte[] frame = CreateDockerStreamFrame(1, payload); // 1 = stdout + + using var stream = new MemoryStream(frame); + var output = new StringBuilder(); + + await DockerContainerEngine.DemuxDockerStream(stream, content => output.Append(content)); + + Assert.AreEqual(logLine, output.ToString()); + } + + [TestMethod] + [TestCategory("BVT")] + public async Task DemuxDockerStream_MultipleFrames_ExtractsAllContent() + { + string line1 = "BASH=/bin/bash\n"; + string line2 = "HOME=/root\n"; + byte[] frame1 = CreateDockerStreamFrame(1, Encoding.UTF8.GetBytes(line1)); + byte[] frame2 = CreateDockerStreamFrame(2, Encoding.UTF8.GetBytes(line2)); // 2 = stderr + + byte[] combined = new byte[frame1.Length + frame2.Length]; + Buffer.BlockCopy(frame1, 0, combined, 0, frame1.Length); + Buffer.BlockCopy(frame2, 0, combined, frame1.Length, frame2.Length); + + using var stream = new MemoryStream(combined); + var output = new StringBuilder(); + + await DockerContainerEngine.DemuxDockerStream(stream, content => output.Append(content)); + + Assert.AreEqual(line1 + line2, output.ToString()); + } + + [TestMethod] + [TestCategory("BVT")] + public async Task DemuxDockerStream_EmptyStream_ProducesNoOutput() + { + using var stream = new MemoryStream(Array.Empty()); + var output = new StringBuilder(); + + await DockerContainerEngine.DemuxDockerStream(stream, content => output.Append(content)); + + Assert.AreEqual(string.Empty, output.ToString()); + } + + [TestMethod] + [TestCategory("BVT")] + public async Task DemuxDockerStream_ZeroLengthPayload_SkipsFrame() + { + string logLine = "actual content\n"; + byte[] emptyFrame = CreateDockerStreamFrame(1, Array.Empty()); + byte[] contentFrame = CreateDockerStreamFrame(1, Encoding.UTF8.GetBytes(logLine)); + + byte[] combined = new byte[emptyFrame.Length + contentFrame.Length]; + Buffer.BlockCopy(emptyFrame, 0, combined, 0, emptyFrame.Length); + Buffer.BlockCopy(contentFrame, 0, combined, emptyFrame.Length, contentFrame.Length); + + using var stream = new MemoryStream(combined); + var output = new StringBuilder(); + + await DockerContainerEngine.DemuxDockerStream(stream, content => output.Append(content)); + + Assert.AreEqual(logLine, output.ToString()); + } + + /// + /// Creates a Docker multiplexed stream frame with the standard 8-byte header. + /// + private static byte[] CreateDockerStreamFrame(byte streamType, byte[] payload) + { + byte[] frame = new byte[8 + payload.Length]; + frame[0] = streamType; + // bytes 1-3 are padding (zeros) + // bytes 4-7 are payload size as big-endian uint32 + frame[4] = (byte)((payload.Length >> 24) & 0xFF); + frame[5] = (byte)((payload.Length >> 16) & 0xFF); + frame[6] = (byte)((payload.Length >> 8) & 0xFF); + frame[7] = (byte)(payload.Length & 0xFF); + Buffer.BlockCopy(payload, 0, frame, 8, payload.Length); + return frame; + } } } \ No newline at end of file diff --git a/VmAgent.Core/Interfaces/DockerContainerEngine.cs b/VmAgent.Core/Interfaces/DockerContainerEngine.cs index 255ef07..c0ddcc4 100644 --- a/VmAgent.Core/Interfaces/DockerContainerEngine.cs +++ b/VmAgent.Core/Interfaces/DockerContainerEngine.cs @@ -509,22 +509,21 @@ public override async Task CollectLogs(string containerId, string logsFolder, IS // we do this for lcow since containers are running on a Hyper-V Linux machine // which the host Windows machine does not have "copy" access to, to get the logs with a FileCopy // this is only supposed to run on LocalMultiplayerAgent running on lcow - StringBuilder sb = new StringBuilder(); Stream logsStream = await _dockerClient.Containers.GetContainerLogsAsync(containerId, new ContainerLogsParameters() {ShowStdout = true, ShowStderr = true}); - using (StreamReader sr = new StreamReader(logsStream)) + + Stopwatch sw = new Stopwatch(); + sw.Start(); + await DemuxDockerStream(logsStream, (content) => { - Stopwatch sw = new Stopwatch(); - while (!sr.EndOfStream) + if (sw.Elapsed.TotalSeconds > 3) // don't flood STDOUT with messages, output one every 3 seconds if logs are too many { - if (sw.Elapsed.Seconds > 3) // don't flood STDOUT with messages, output one every 3 seconds if logs are too many - { - _logger.LogVerbose($"Gathering logs for container {containerId}, please wait..."); - sw.Restart(); - } - _systemOperations.FileAppendAllText(destinationFileName, sr.ReadLine() + Environment.NewLine); + _logger.LogVerbose($"Gathering logs for container {containerId}, please wait..."); + sw.Restart(); } - } + _systemOperations.FileAppendAllText(destinationFileName, content); + }); + _logger.LogVerbose($"Written logs for container {containerId} to {destinationFileName}."); } else @@ -544,6 +543,60 @@ public override async Task CollectLogs(string containerId, string logsFolder, IS } } + /// + /// Reads a Docker multiplexed stream and extracts the log content, stripping the 8-byte binary headers. + /// Docker uses a multiplexed stream format for container logs when TTY is not enabled: + /// - Bytes 0: stream type (1=stdout, 2=stderr) + /// - Bytes 1-3: padding (zeros) + /// - Bytes 4-7: payload size as big-endian uint32 + /// - Followed by payload bytes of the specified size + /// + internal static async Task DemuxDockerStream(Stream multiplexedStream, Action writeContent) + { + byte[] header = new byte[8]; + while (true) + { + int headerBytesRead = await ReadExactAsync(multiplexedStream, header, 0, 8); + if (headerBytesRead < 8) + { + break; + } + + int payloadSize = (header[4] << 24) | (header[5] << 16) | (header[6] << 8) | header[7]; + + if (payloadSize == 0) + { + continue; + } + + byte[] payload = new byte[payloadSize]; + int payloadBytesRead = await ReadExactAsync(multiplexedStream, payload, 0, payloadSize); + + string content = Encoding.UTF8.GetString(payload, 0, payloadBytesRead); + writeContent(content); + + if (payloadBytesRead < payloadSize) + { + break; + } + } + } + + private static async Task ReadExactAsync(Stream stream, byte[] buffer, int offset, int count) + { + int totalRead = 0; + while (totalRead < count) + { + int bytesRead = await stream.ReadAsync(buffer, offset + totalRead, count - totalRead); + if (bytesRead == 0) + { + break; + } + totalRead += bytesRead; + } + return totalRead; + } + public override async Task TryDelete(string id) { bool result = true;