diff --git a/VERSION b/VERSION index c70f42b234..3faeb7bb98 100644 --- a/VERSION +++ b/VERSION @@ -1 +1 @@ -2.1.47 \ No newline at end of file +2.1.48 \ No newline at end of file diff --git a/src/VirtualClient/VirtualClient.Common.UnitTests/ProcessExtensionsTests.cs b/src/VirtualClient/VirtualClient.Common.UnitTests/ProcessExtensionsTests.cs index cc97fa5f61..24717e64c3 100644 --- a/src/VirtualClient/VirtualClient.Common.UnitTests/ProcessExtensionsTests.cs +++ b/src/VirtualClient/VirtualClient.Common.UnitTests/ProcessExtensionsTests.cs @@ -4,7 +4,9 @@ namespace VirtualClient.Common { using System; + using System.Collections.Generic; using System.IO; + using System.Linq; using System.Threading; using System.Threading.Tasks; using NUnit.Framework; @@ -66,5 +68,42 @@ public void WaitForResponseAsyncExtensionThrowsIfTheExpectedResponseIsNotReceive Assert.ThrowsAsync( () => this.mockProcess.WaitForResponseAsync("NeverGonnaShow", CancellationToken.None, timeout: TimeSpan.Zero)); } + + [Test] + public void ProcessDetailsCloneCreatesANewInstanceWithTheSameValues() + { + ProcessDetails process1 = new ProcessDetails + { + Id = -1, + CommandLine = Guid.NewGuid().ToString(), + ExitTime = DateTime.UtcNow, + ExitCode = -2, + StandardOutput = Guid.NewGuid().ToString(), + StandardError = Guid.NewGuid().ToString(), + StartTime = DateTime.MinValue, + ToolName = Guid.NewGuid().ToString(), + WorkingDirectory = Guid.NewGuid().ToString(), + Results = new[] + { + new KeyValuePair(Guid.NewGuid().ToString(), Guid.NewGuid().ToString()), + new KeyValuePair(Guid.NewGuid().ToString(), Guid.NewGuid().ToString()) + } + }; + + ProcessDetails process2 = process1.Clone(); + + Assert.AreNotEqual(process1, process2); + + Assert.AreEqual(process1.Id, process2.Id); + Assert.AreEqual(process1.CommandLine, process2.CommandLine); + Assert.AreEqual(process1.ExitTime, process2.ExitTime); + Assert.AreEqual(process1.ExitCode, process2.ExitCode); + Assert.AreEqual(process1.StandardOutput, process2.StandardOutput); + Assert.AreEqual(process1.StandardError, process2.StandardError); + Assert.AreEqual(process1.StartTime, process2.StartTime); + Assert.AreEqual(process1.ToolName, process2.ToolName); + Assert.AreEqual(process1.WorkingDirectory, process2.WorkingDirectory); + Assert.AreEqual(process1.Results.Count(), process2.Results.Count()); + } } } diff --git a/src/VirtualClient/VirtualClient.Common/ProcessDetails.cs b/src/VirtualClient/VirtualClient.Common/ProcessDetails.cs index 37fbee3f8a..d27fbd20f1 100644 --- a/src/VirtualClient/VirtualClient.Common/ProcessDetails.cs +++ b/src/VirtualClient/VirtualClient.Common/ProcessDetails.cs @@ -3,6 +3,7 @@ using System; using System.Collections.Generic; +using System.Linq; namespace VirtualClient.Common { @@ -78,5 +79,36 @@ public TimeSpan? ElapsedTime /// Working Directory. /// public string WorkingDirectory { get; set; } + + /// + /// Returns a clone of the current instance. + /// + /// + /// A clone of the current instance. + /// + public virtual ProcessDetails Clone() + { + ProcessDetails clonedDetails = new ProcessDetails + { + Id = this.Id, + CommandLine = this.CommandLine, + ExitTime = this.ExitTime, + ExitCode = this.ExitCode, + StandardOutput = this.StandardOutput, + StandardError = this.StandardError, + StartTime = this.StartTime, + ToolName = this.ToolName, + WorkingDirectory = this.WorkingDirectory, + Results = new List>() + }; + + // Always create a new collection instance when Results is non-null. + if (this.Results != null) + { + clonedDetails.Results = this.Results.ToList(); + } + + return clonedDetails; + } } } \ No newline at end of file diff --git a/src/VirtualClient/VirtualClient.Contracts.UnitTests/VirtualClientLoggingExtensionsTests.cs b/src/VirtualClient/VirtualClient.Contracts.UnitTests/VirtualClientLoggingExtensionsTests.cs index 9114be8bf3..896b6b6871 100644 --- a/src/VirtualClient/VirtualClient.Contracts.UnitTests/VirtualClientLoggingExtensionsTests.cs +++ b/src/VirtualClient/VirtualClient.Contracts.UnitTests/VirtualClientLoggingExtensionsTests.cs @@ -1015,7 +1015,7 @@ public async Task LogProcessDetailsAsyncExtensionEmitsTheExpectedProcessInformat StandardOutput = expectedStandardOutput != null ? new Common.ConcurrentBuffer(new StringBuilder(expectedStandardOutput)) : null, StandardError = expectedStandardError != null ? new Common.ConcurrentBuffer(new StringBuilder(expectedStandardError)) : null }; - + string expectedResults = "Any results output by the process."; bool expectedProcessDetailsCaptured = false; bool expectedProcessResultsCaptured = false; @@ -1171,7 +1171,7 @@ public async Task LogProcessDetailsExtensionEmitsTheExpectedProcessInformationAs { Assert.AreEqual(LogLevel.Information, level, $"Log level not matched"); Assert.IsInstanceOf(state); - + if (eventInfo.Name == $"{nameof(TestExecutor)}.{expectedToolset}.ProcessDetails") { @@ -1519,7 +1519,7 @@ public async Task LogProcessDetailsExtensionWritesTheExpectedProcessInformationT expectedLogFileWritten = true; }); - + await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), expectedToolset, logToTelemetry: false, logToFile: true) .ConfigureAwait(false); @@ -1591,7 +1591,7 @@ public async Task LogProcessDetailsExtensionCreatesTheLogDirectoryIfItDoesNotExi { InMemoryProcess process = new InMemoryProcess(); TestExecutor component = new TestExecutor(this.mockFixture); - + string expectedLogPath = this.mockFixture.GetLogsPath(nameof(TestExecutor).ToLowerInvariant()); await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: false, logToFile: true) @@ -2102,7 +2102,7 @@ public void LogSystemEventExtensionLogsTheExpectedEvents(LogLevel expectedEventL }; this.mockLogger.Object.LogSystemEvent( - expectedEventType, + expectedEventType, expectedEventSource, expectedEventId, expectedEventLevel, @@ -2319,6 +2319,273 @@ public void ObscureSecretsExtensionDoesNotModifyDataInTheOriginalParameters() } } + [Test] + public async Task LogProcessDetailsDoesNotSplitTelemetryWhenCombinedOutputIsBelowMaxChars() + { + // Scenario: + // When enableOutputSplit is true BUT combined output is below maxChars, no splitting should occur. + + int maxCharlimit = 125000; + string smallOutput = new string('A', maxCharlimit /3 ); + string smallError = new string('B', maxCharlimit / 5); + // Total = 100,000 which is below 125,000 + + InMemoryProcess process = new InMemoryProcess + { + ExitCode = 0, + StartInfo = new ProcessStartInfo + { + FileName = "AnyCommand.exe", + Arguments = "--any=arguments" + }, + StandardOutput = new Common.ConcurrentBuffer(new StringBuilder(smallOutput)), + StandardError = new Common.ConcurrentBuffer(new StringBuilder(smallError)) + }; + + this.mockLogger + .Setup(logger => logger.Log(It.IsAny(), It.IsAny(), It.IsAny(), null, null)) + .Callback>((level, eventId, state, exc, formatter) => + { + if (eventId.Name.Contains("ProcessDetails")) + { + // Verify no chunk context is added + Assert.IsFalse(state.Properties.ContainsKey("standardOutputPart")); + Assert.IsFalse(state.Properties.ContainsKey("standardErrorPart")); + } + }); + + TestExecutor component = new TestExecutor(this.mockFixture); + component.Logger = this.mockLogger.Object; + await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit).ConfigureAwait(false); + + // Should only log ONE event (no splitting needed) + this.mockLogger.Verify(logger => logger.Log(It.IsAny(), It.IsAny(), It.IsAny(), null, null), Times.Once); + } + + [Test] + public async Task LogProcessDetailsSplitTelemetryWhenCombinedOutputIsAboveMaxChars() + { + // Scenario: + // Splitting should occur ONLY when enableOutputSplit=true AND combined output > maxChars + + int maxCharlimit = 125000; + string largeOutput = new string('A', maxCharlimit * 2 ); // Requires 2 chunks at 125K each + string largeError = new string('B', maxCharlimit * 5); // Requires 5 chunk + + InMemoryProcess process = new InMemoryProcess + { + ExitCode = 0, + StartInfo = new ProcessStartInfo + { + FileName = "AnyCommand.exe", + Arguments = "--any=arguments" + }, + StandardOutput = new Common.ConcurrentBuffer(new StringBuilder(largeOutput)), + StandardError = new Common.ConcurrentBuffer(new StringBuilder(largeError)) + }; + + int standardOutputEventCount = 0; + int standardErrorEventCount = 0; + + this.mockLogger + .Setup(logger => logger.Log(It.IsAny(), It.IsAny(), It.IsAny(), null, null)) + .Callback>((level, eventId, state, exc, formatter) => + { + if (eventId.Name.Contains("ProcessDetails") && state is EventContext context) + { + if (context.Properties.ContainsKey("standardOutputPart")) + { + standardOutputEventCount++; + } + else if (context.Properties.ContainsKey("standardErrorPart")) + { + standardErrorEventCount++; + } + } + }); + + TestExecutor component = new TestExecutor(this.mockFixture); + component.Logger = this.mockLogger.Object; + await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit).ConfigureAwait(false); + + // Verify splitting occurred + Assert.AreEqual(2, standardOutputEventCount, "Should create 2 events for standard output chunks"); + Assert.AreEqual(5, standardErrorEventCount, "Should create 1 event for standard error chunk"); + + this.mockLogger.Verify(logger => logger.Log(It.IsAny(), It.IsAny(), It.IsAny(), null, null), Times.Exactly(7)); + } + + [Test] + public async Task LogProcessDetailsSplitTelemetryCapturesAllDataWithoutTruncation() + { + // Scenario: + // When splitting occurs, verify ALL data is captured without any truncation. + + int maxCharlimit = 125000; + string expectedOutput = new string('X', maxCharlimit * 3); + string expectedError = new string('Y', maxCharlimit * 9); + + InMemoryProcess process = new InMemoryProcess + { + ExitCode = 0, + StartInfo = new ProcessStartInfo + { + FileName = "AnyCommand.exe", + Arguments = "--any=arguments" + }, + StandardOutput = new Common.ConcurrentBuffer(new StringBuilder(expectedOutput)), + StandardError = new Common.ConcurrentBuffer(new StringBuilder(expectedError)) + }; + + StringBuilder capturedStandardOutput = new StringBuilder(); + StringBuilder capturedStandardError = new StringBuilder(); + + this.mockLogger + .Setup(logger => logger.Log(It.IsAny(), It.IsAny(), It.IsAny(), null, null)) + .Callback>((level, eventId, state, exc, formatter) => + { + if (eventId.Name.Contains("ProcessDetails") && state is EventContext context) + { + if (context.Properties.TryGetValue("process", out object processContext)) + { + var processObj = JObject.FromObject(processContext); + string stdOut = processObj["standardOutput"]?.ToString(); + string stdErr = processObj["standardError"]?.ToString(); + + if (!string.IsNullOrEmpty(stdOut)) + { + capturedStandardOutput.Append(stdOut); + } + + if (!string.IsNullOrEmpty(stdErr)) + { + capturedStandardError.Append(stdErr); + } + } + } + }); + + TestExecutor component = new TestExecutor(this.mockFixture); + component.Logger = this.mockLogger.Object; + await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit).ConfigureAwait(false); + + // Verify NO truncation occurred + Assert.AreEqual(expectedOutput.Length, capturedStandardOutput.Length, "All standard output should be captured"); + Assert.AreEqual(expectedError.Length, capturedStandardError.Length, "All standard error should be captured"); + Assert.AreEqual(expectedOutput, capturedStandardOutput.ToString(), "Standard output content should match exactly"); + Assert.AreEqual(expectedError, capturedStandardError.ToString(), "Standard error content should match exactly"); + this.mockLogger.Verify(logger => logger.Log(It.IsAny(), It.IsAny(), It.IsAny(), null, null), Times.Exactly(12)); + } + + [Test] + public async Task LogProcessDetailsSplitTelemetryIncludesChunkPartNumberInContext() + { + // Scenario: + // Verify that split events include chunk part numbers for tracking. + + int maxCharlimit = 125000; + string largeOutput = new string('A', 250000); // Will create 2 chunks + + InMemoryProcess process = new InMemoryProcess + { + ExitCode = 0, + StartInfo = new ProcessStartInfo + { + FileName = "AnyCommand.exe" + }, + StandardOutput = new Common.ConcurrentBuffer(new StringBuilder(largeOutput)) + }; + + List chunkParts = new List(); + + this.mockLogger + .Setup(logger => logger.Log(It.IsAny(), It.IsAny(), It.IsAny(), null, null)) + .Callback>((level, eventId, state, exc, formatter) => + { + if (state is EventContext context && context.Properties.ContainsKey("standardOutputPart")) + { + chunkParts.Add(Convert.ToInt32(context.Properties["standardOutputPart"])); + } + }); + + TestExecutor component = new TestExecutor(this.mockFixture); + component.Logger = this.mockLogger.Object; + await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit).ConfigureAwait(false); + + // Verify chunk parts are numbered sequentially starting from 1 + Assert.AreEqual(2, chunkParts.Count, "Should have 2 chunk parts"); + Assert.AreEqual(1, chunkParts[0], "First chunk should be numbered 1"); + Assert.AreEqual(2, chunkParts[1], "Second chunk should be numbered 2"); + this.mockLogger.Verify(logger => logger.Log(It.IsAny(), It.IsAny(), It.IsAny(), null, null), Times.Exactly(2)); + } + + [Test] + public async Task LogProcessDetailsSplitsStandardOutputAndErrorSeparately() + { + // Scenario: + // When standard output and standard error equals maxChars exactly, split output and error separately. + int maxCharlimit = 125000; + string output = new string('A', maxCharlimit); // Exactly at the limit + string error = new string('B', maxCharlimit); // Exactly at the limit + + InMemoryProcess process = new InMemoryProcess + { + ExitCode = 0, + StartInfo = new ProcessStartInfo + { + FileName = "AnyCommand.exe" + }, + StandardOutput = new Common.ConcurrentBuffer(new StringBuilder(output)), + StandardError = new Common.ConcurrentBuffer(new StringBuilder(output)) + }; + + this.mockLogger.Setup(logger => logger.Log(It.IsAny(), It.IsAny(), It.IsAny(), null, null)); + + TestExecutor component = new TestExecutor(this.mockFixture); + component.Logger = this.mockLogger.Object; + await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit).ConfigureAwait(false); + + this.mockLogger.Verify(logger => logger.Log(It.IsAny(), It.IsAny(), It.IsAny(), null, null), Times.Exactly(2)); + } + + [Test] + public async Task LogProcessDetailsSplitTelemetryHandlesBoundaryConditionOneCharOverMaxChars() + { + // Scenario: + // When combined output is just 1 char over maxChars, splitting should occur. + int maxCharlimit = 125000; + string output = new string('A', maxCharlimit + 1); // One character over the limit + + InMemoryProcess process = new InMemoryProcess + { + ExitCode = 0, + StartInfo = new ProcessStartInfo + { + FileName = "AnyCommand.exe" + }, + StandardOutput = new Common.ConcurrentBuffer(new StringBuilder(output)) + }; + + int eventCount = 0; + + this.mockLogger + .Setup(logger => logger.Log(It.IsAny(), It.IsAny(), It.IsAny(), null, null)) + .Callback>((level, eventId, state, exc, formatter) => + { + if (eventId.Name.Contains("ProcessDetails")) + { + eventCount++; + } + }); + + TestExecutor component = new TestExecutor(this.mockFixture); + component.Logger = this.mockLogger.Object; + await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit).ConfigureAwait(false); + + // Should split when even 1 char over the limit + Assert.AreEqual(2, eventCount, "Should split when output exceeds maxChars by even 1 character"); + } + private static Tuple GetAccessTokenPair() { // Note: diff --git a/src/VirtualClient/VirtualClient.Core/VirtualClientLoggingExtensions.cs b/src/VirtualClient/VirtualClient.Core/VirtualClientLoggingExtensions.cs index 72753eba3d..838e456974 100644 --- a/src/VirtualClient/VirtualClient.Core/VirtualClientLoggingExtensions.cs +++ b/src/VirtualClient/VirtualClient.Core/VirtualClientLoggingExtensions.cs @@ -154,7 +154,7 @@ internal static void LogProcessDetails(this ILogger logger, ProcessDetails proce componentType.ThrowIfNullOrWhiteSpace(nameof(componentType)); processDetails.ThrowIfNull(nameof(processDetails)); telemetryContext.ThrowIfNull(nameof(telemetryContext)); - + try { // Obscure sensitive data in the command line @@ -172,10 +172,45 @@ internal static void LogProcessDetails(this ILogger logger, ProcessDetails proce !string.IsNullOrWhiteSpace(processDetails.ToolName) ? $"{componentType}.{processDetails.ToolName}" : componentType, string.Empty); - logger.LogMessage( - $"{eventNamePrefix}.ProcessDetails", - LogLevel.Information, - telemetryContext.Clone().AddProcessDetails(processDetails, maxChars: logToTelemetryMaxChars)); + if (processDetails.StandardOutput.Length + processDetails.StandardError.Length > logToTelemetryMaxChars) + { + // Handle splitting standard output and error if enabled and necessary + List standardOutputChunks = VirtualClientLoggingExtensions.SplitString(processDetails.StandardOutput, logToTelemetryMaxChars); + List standardErrorChunks = VirtualClientLoggingExtensions.SplitString(processDetails.StandardError, logToTelemetryMaxChars); + + for (int i = 0; i < standardOutputChunks.Count; i++) + { + ProcessDetails chunkedProcess = processDetails.Clone(); + chunkedProcess.StandardOutput = standardOutputChunks[i]; + chunkedProcess.StandardError = null; // Only include standard error in one of the events (to avoid duplication). + EventContext context = telemetryContext.Clone() + .AddContext("standardOutputPart", i + 1) + .AddProcessDetails(chunkedProcess, maxChars: logToTelemetryMaxChars); + + logger.LogMessage($"{eventNamePrefix}.ProcessDetails", LogLevel.Information, context); + + } + + for (int j = 0; j < standardErrorChunks.Count; j++) + { + ProcessDetails chunkedProcess = processDetails.Clone(); + chunkedProcess.StandardOutput = null; // Only include standard output in one of the events (to avoid duplication). + chunkedProcess.StandardError = standardErrorChunks[j]; + + EventContext context = telemetryContext.Clone() + .AddContext("standardErrorPart", j + 1) + .AddProcessDetails(chunkedProcess, maxChars: logToTelemetryMaxChars); + + logger.LogMessage($"{eventNamePrefix}.ProcessDetails", LogLevel.Information, context); + } + } + else + { + logger.LogMessage( + $"{eventNamePrefix}.ProcessDetails", + LogLevel.Information, + telemetryContext.Clone().AddProcessDetails(processDetails, maxChars: logToTelemetryMaxChars)); + } if (processDetails.Results?.Any() == true) { @@ -408,5 +443,26 @@ private static string GetSafeFileName(string fileName, bool timestamped = true) return effectiveLogFileName.ToLowerInvariant(); } + + /// + /// Splits a given string into a list of substrings, each with a maximum specified length. + /// Useful for processing or transmitting large strings in manageable chunks. + /// + /// The original string to be split. If null, it will be treated as an empty string. + /// The maximum length of each chunk. Defaults to 125,000 characters. + /// A list of substrings, each with a length up to the specified chunk size. + private static List SplitString(string inputString, int chunkSize = 125000) + { + string finalString = inputString ?? string.Empty; + + var result = new List(); + for (int i = 0; i < finalString.Length; i += chunkSize) + { + int length = Math.Min(chunkSize, finalString.Length - i); + result.Add(finalString.Substring(i, length)); + } + + return result; + } } } diff --git a/src/VirtualClient/VirtualClient.Monitors/ExecuteCommandMonitor.cs b/src/VirtualClient/VirtualClient.Monitors/ExecuteCommandMonitor.cs index d3061bd6aa..4b2c3fd0d3 100644 --- a/src/VirtualClient/VirtualClient.Monitors/ExecuteCommandMonitor.cs +++ b/src/VirtualClient/VirtualClient.Monitors/ExecuteCommandMonitor.cs @@ -354,7 +354,7 @@ private void CaptureEventInformation(IProcessProxy process, EventContext telemet standardError = $"{standardError.Substring(0, MaxOutputLength)}..."; } - string eventType = !string.IsNullOrWhiteSpace(this.MonitorEventType) + string eventType = !string.IsNullOrWhiteSpace(this.MonitorEventType) ? this.MonitorEventType : "system.monitor";