From 4c4d5e6511ec6a079a6ef19d7e065089a6d5ff66 Mon Sep 17 00:00:00 2001 From: nchapagain001 <165215502+nchapagain001@users.noreply.github.com> Date: Wed, 8 Oct 2025 16:25:17 -0700 Subject: [PATCH 1/6] Chunking telemetry. --- .../VirtualClient.Common/ProcessDetails.cs | 31 +++++++ .../VirtualClientLoggingExtensions.cs | 89 +++++++++++++++++-- 2 files changed, 111 insertions(+), 9 deletions(-) diff --git a/src/VirtualClient/VirtualClient.Common/ProcessDetails.cs b/src/VirtualClient/VirtualClient.Common/ProcessDetails.cs index f113afeb39..78f512a8d7 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,35 @@ 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 + }; + + // Create a new list to avoid sharing the same collection reference + if (this.Results?.Any() == true) + { + clonedDetails.Results = new List(this.Results); + } + + return clonedDetails; + } } } \ No newline at end of file diff --git a/src/VirtualClient/VirtualClient.Core/VirtualClientLoggingExtensions.cs b/src/VirtualClient/VirtualClient.Core/VirtualClientLoggingExtensions.cs index f85180f850..9f6b973d82 100644 --- a/src/VirtualClient/VirtualClient.Core/VirtualClientLoggingExtensions.cs +++ b/src/VirtualClient/VirtualClient.Core/VirtualClientLoggingExtensions.cs @@ -52,14 +52,18 @@ public static class VirtualClientLoggingExtensions /// The name to use for the log file when writing to the file system. Default = component 'Scenario' parameter value. /// True if any log files generated should be prefixed with timestamps. Default = true. /// True to request the file be uploaded when a content store is defined. + /// + /// When true, splits the standard output and error into multiple telemetry events if they exceed maxChars. + /// When false, truncates the standard output/error at maxChars (existing behavior). + /// public static Task LogProcessDetailsAsync( - this VirtualClientComponent component, IProcessProxy process, EventContext telemetryContext, string toolName = null, IEnumerable results = null, bool logToTelemetry = true, bool logToFile = true, int logToTelemetryMaxChars = 125000, string logFileName = null, bool timestamped = true, bool upload = true) + this VirtualClientComponent component, IProcessProxy process, EventContext telemetryContext, string toolName = null, IEnumerable results = null, bool logToTelemetry = true, bool logToFile = true, int logToTelemetryMaxChars = 125000, string logFileName = null, bool timestamped = true, bool upload = true, bool enableOutputSplit = false) { component.ThrowIfNull(nameof(component)); process.ThrowIfNull(nameof(process)); telemetryContext.ThrowIfNull(nameof(telemetryContext)); - return LogProcessDetailsAsync(component, process.ToProcessDetails(toolName, results), telemetryContext, logToTelemetry, logToFile, logToTelemetryMaxChars, logFileName, timestamped, upload); + return LogProcessDetailsAsync(component, process.ToProcessDetails(toolName, results), telemetryContext, logToTelemetry, logToFile, logToTelemetryMaxChars, logFileName, timestamped, upload, enableOutputSplit); } /// @@ -84,7 +88,11 @@ public static Task LogProcessDetailsAsync( /// The name to use for the log file when writing to the file system. Default = component 'Scenario' parameter value. /// True if any log files generated should be prefixed with timestamps. Default = true. /// True to request the file be uploaded when a content store is defined. - public static async Task LogProcessDetailsAsync(this VirtualClientComponent component, ProcessDetails processDetails, EventContext telemetryContext, bool logToTelemetry = true, bool logToFile = true, int logToTelemetryMaxChars = 125000, string logFileName = null, bool timestamped = true, bool upload = true) + /// + /// When true, splits the standard output and error into multiple telemetry events if they exceed maxChars. + /// When false, truncates the standard output/error at maxChars (existing behavior). + /// + public static async Task LogProcessDetailsAsync(this VirtualClientComponent component, ProcessDetails processDetails, EventContext telemetryContext, bool logToTelemetry = true, bool logToFile = true, int logToTelemetryMaxChars = 125000, string logFileName = null, bool timestamped = true, bool upload = true, bool enableOutputSplit = false) { component.ThrowIfNull(nameof(component)); processDetails.ThrowIfNull(nameof(processDetails)); @@ -98,7 +106,7 @@ public static async Task LogProcessDetailsAsync(this VirtualClientComponent comp { try { - component.Logger?.LogProcessDetails(processDetails, component.TypeName, telemetryContext, logToTelemetryMaxChars); + component.Logger?.LogProcessDetails(processDetails, component.TypeName, telemetryContext, logToTelemetryMaxChars, enableOutputSplit: enableOutputSplit); } catch (Exception exc) { @@ -150,13 +158,19 @@ public static async Task LogProcessDetailsAsync(this VirtualClientComponent comp /// without risking data loss during upload because the message exceeds thresholds. Default = 125,000 chars. In relativity /// there are about 3000 characters in an average single-spaced page of text. /// - internal static void LogProcessDetails(this ILogger logger, ProcessDetails processDetails, string componentType, EventContext telemetryContext, int logToTelemetryMaxChars = 125000) + /// + /// When true, splits the standard output and error into multiple telemetry events if they exceed maxChars. + /// When false, truncates the standard output/error at maxChars (existing behavior). + /// + internal static void LogProcessDetails(this ILogger logger, ProcessDetails processDetails, string componentType, EventContext telemetryContext, int logToTelemetryMaxChars = 125000, bool enableOutputSplit = false) { logger.ThrowIfNull(nameof(logger)); componentType.ThrowIfNullOrWhiteSpace(nameof(componentType)); processDetails.ThrowIfNull(nameof(processDetails)); telemetryContext.ThrowIfNull(nameof(telemetryContext)); + telemetryContext.AddContext(nameof(enableOutputSplit), enableOutputSplit); + try { // Obscure sensitive data in the command line @@ -174,10 +188,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 (enableOutputSplit) + { + // 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("standardOutputChunkPart", 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("standardErrorChunkPart", 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) { @@ -186,6 +235,7 @@ internal static void LogProcessDetails(this ILogger logger, ProcessDetails proce LogLevel.Information, telemetryContext.Clone().AddProcessResults(processDetails, maxChars: logToTelemetryMaxChars)); } + } catch { @@ -406,5 +456,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; + } } } From 698a7c7a5a1f281839a7c89b5bbec1a9a8a17a93 Mon Sep 17 00:00:00 2001 From: nchapagain001 <165215502+nchapagain001@users.noreply.github.com> Date: Thu, 9 Oct 2025 09:13:48 -0700 Subject: [PATCH 2/6] ensure no splitting when it doesn't exceed maxChar --- .../VirtualClient.Core/VirtualClientLoggingExtensions.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/VirtualClient/VirtualClient.Core/VirtualClientLoggingExtensions.cs b/src/VirtualClient/VirtualClient.Core/VirtualClientLoggingExtensions.cs index 9f6b973d82..cd63d406ef 100644 --- a/src/VirtualClient/VirtualClient.Core/VirtualClientLoggingExtensions.cs +++ b/src/VirtualClient/VirtualClient.Core/VirtualClientLoggingExtensions.cs @@ -188,7 +188,7 @@ internal static void LogProcessDetails(this ILogger logger, ProcessDetails proce !string.IsNullOrWhiteSpace(processDetails.ToolName) ? $"{componentType}.{processDetails.ToolName}" : componentType, string.Empty); - if (enableOutputSplit) + if (enableOutputSplit && (processDetails.StandardOutput.Length + processDetails.StandardError.Length > logToTelemetryMaxChars)) { // Handle splitting standard output and error if enabled and necessary List standardOutputChunks = VirtualClientLoggingExtensions.SplitString(processDetails.StandardOutput, logToTelemetryMaxChars); From 10e92ef243b1ead2b5ec0f9cb667abe1bffad201 Mon Sep 17 00:00:00 2001 From: nchapagain001 <165215502+nchapagain001@users.noreply.github.com> Date: Thu, 9 Oct 2025 09:19:50 -0700 Subject: [PATCH 3/6] Process Details Clone --- .../ProcessExtensionsTests.cs | 30 +++++++++++++++++++ 1 file changed, 30 insertions(+) diff --git a/src/VirtualClient/VirtualClient.Common.UnitTests/ProcessExtensionsTests.cs b/src/VirtualClient/VirtualClient.Common.UnitTests/ProcessExtensionsTests.cs index cc97fa5f61..dd73ac9896 100644 --- a/src/VirtualClient/VirtualClient.Common.UnitTests/ProcessExtensionsTests.cs +++ b/src/VirtualClient/VirtualClient.Common.UnitTests/ProcessExtensionsTests.cs @@ -66,5 +66,35 @@ 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() + }; + + 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); + } } } From 43b74f3648351252fc908373621a7175c306f41e Mon Sep 17 00:00:00 2001 From: nchapagain001 <165215502+nchapagain001@users.noreply.github.com> Date: Wed, 15 Oct 2025 13:15:08 -0700 Subject: [PATCH 4/6] Adding test cases. --- .../VirtualClientLoggingExtensionsTests.cs | 324 +++++++++++++++++- .../VirtualClientLoggingExtensions.cs | 5 +- 2 files changed, 320 insertions(+), 9 deletions(-) diff --git a/src/VirtualClient/VirtualClient.Contracts.UnitTests/VirtualClientLoggingExtensionsTests.cs b/src/VirtualClient/VirtualClient.Contracts.UnitTests/VirtualClientLoggingExtensionsTests.cs index 336ffa2ee1..113ec4a06c 100644 --- a/src/VirtualClient/VirtualClient.Contracts.UnitTests/VirtualClientLoggingExtensionsTests.cs +++ b/src/VirtualClient/VirtualClient.Contracts.UnitTests/VirtualClientLoggingExtensionsTests.cs @@ -1016,7 +1016,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") { @@ -1518,7 +1518,7 @@ public async Task LogProcessDetailsExtensionWritesTheExpectedProcessInformationT expectedLogFileWritten = true; }); - + await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), expectedToolset, logToTelemetry: false, logToFile: true) .ConfigureAwait(false); @@ -1578,7 +1578,7 @@ public async Task LogProcessDetailsToFileSystemAsyncExtensionWritesTheExpectedPr expectedLogFileWritten = true; }); - + await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), results: new List { expectedResults }, logToTelemetry: false, logToFile: true) .ConfigureAwait(false); @@ -1590,7 +1590,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) @@ -2101,7 +2101,7 @@ public void LogSystemEventExtensionLogsTheExpectedEvents(LogLevel expectedEventL }; this.mockLogger.Object.LogSystemEvent( - expectedEventType, + expectedEventType, expectedEventSource, expectedEventId, expectedEventLevel, @@ -2318,6 +2318,318 @@ public void ObscureSecretsExtensionDoesNotModifyDataInTheOriginalParameters() } } + [Test] + public async Task LogProcessDetailsDoesNotSplitOutputWhenEnableOutputSplitIsFalse() + { + int maxCharlimit = 125000; + + // Scenario: + // When enableOutputSplit is false, output should NOT be split even if it exceeds maxChars. + // The truncation behavior should apply instead. + + string largeOutput = new string('A', maxCharlimit * 2); + string largeError = new string('B', maxCharlimit * 2); + + 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)) + }; + + 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("standardOutputChunkPart")); + Assert.IsFalse(state.Properties.ContainsKey("standardErrorChunkPart")); + } + }); + + + TestExecutor component = new TestExecutor(this.mockFixture); + component.Logger = this.mockLogger.Object; + await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit, enableOutputSplit: false).ConfigureAwait(false); + + // Should only log ONE event (no splitting) + this.mockLogger.Verify(logger => logger.Log(It.IsAny(), It.IsAny(), It.IsAny(), null, null), Times.Once); + } + + [Test] + public async Task LogProcessDetailsDoesNotSplitWhenCombinedOutputIsBelowMaxChars() + { + // 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("standardOutputChunkPart")); + Assert.IsFalse(state.Properties.ContainsKey("standardErrorChunkPart")); + } + }); + + TestExecutor component = new TestExecutor(this.mockFixture); + component.Logger = this.mockLogger.Object; + await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit, enableOutputSplit: false).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 LogProcessDetailsSplitsOutputOnlyWhenBothConditionsAreMet() + { + // 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("standardOutputChunkPart")) + { + standardOutputEventCount++; + } + else if (context.Properties.ContainsKey("standardErrorChunkPart")) + { + standardErrorEventCount++; + } + } + }); + + TestExecutor component = new TestExecutor(this.mockFixture); + component.Logger = this.mockLogger.Object; + await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit, enableOutputSplit: true).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 LogProcessDetailsSplitCapturesAllDataWithoutTruncation() + { + // 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, enableOutputSplit: true).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 LogProcessDetailsSplitIncludesChunkPartNumberInContext() + { + // 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("standardOutputChunkPart")) + { + chunkParts.Add(Convert.ToInt32(context.Properties["standardOutputChunkPart"])); + } + }); + + TestExecutor component = new TestExecutor(this.mockFixture); + component.Logger = this.mockLogger.Object; + await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit, enableOutputSplit: true).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 LogProcessDetailsSplitStandardOutputAndErrorSeparately() + { + // 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, enableOutputSplit: true).ConfigureAwait(false); + + this.mockLogger.Verify(logger => logger.Log(It.IsAny(), It.IsAny(), It.IsAny(), null, null), Times.Exactly(2)); + } + + [Test] + public async Task LogProcessDetailsSplitHandlesBoundaryConditionOneCharOverMaxChars() + { + // 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, enableOutputSplit: true).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 cd63d406ef..f52aa27ba7 100644 --- a/src/VirtualClient/VirtualClient.Core/VirtualClientLoggingExtensions.cs +++ b/src/VirtualClient/VirtualClient.Core/VirtualClientLoggingExtensions.cs @@ -168,9 +168,8 @@ internal static void LogProcessDetails(this ILogger logger, ProcessDetails proce componentType.ThrowIfNullOrWhiteSpace(nameof(componentType)); processDetails.ThrowIfNull(nameof(processDetails)); telemetryContext.ThrowIfNull(nameof(telemetryContext)); - telemetryContext.AddContext(nameof(enableOutputSplit), enableOutputSplit); - + try { // Obscure sensitive data in the command line @@ -189,7 +188,7 @@ internal static void LogProcessDetails(this ILogger logger, ProcessDetails proce string.Empty); if (enableOutputSplit && (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); From e6be3ca5bebdb799c942df53a8a5fd997ea4d960 Mon Sep 17 00:00:00 2001 From: nchapagain001 <165215502+nchapagain001@users.noreply.github.com> Date: Wed, 15 Oct 2025 13:45:46 -0700 Subject: [PATCH 5/6] Cleaning up --- VERSION | 2 +- .../VirtualClientLoggingExtensionsTests.cs | 28 +++++++++---------- .../VirtualClientLoggingExtensions.cs | 18 ++++++------ 3 files changed, 24 insertions(+), 24 deletions(-) diff --git a/VERSION b/VERSION index 1fbecce930..e3baf30b73 100644 --- a/VERSION +++ b/VERSION @@ -1 +1 @@ -2.1.34 \ No newline at end of file +2.1.35 \ 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 113ec4a06c..65a6d257d3 100644 --- a/src/VirtualClient/VirtualClient.Contracts.UnitTests/VirtualClientLoggingExtensionsTests.cs +++ b/src/VirtualClient/VirtualClient.Contracts.UnitTests/VirtualClientLoggingExtensionsTests.cs @@ -2319,7 +2319,7 @@ public void ObscureSecretsExtensionDoesNotModifyDataInTheOriginalParameters() } [Test] - public async Task LogProcessDetailsDoesNotSplitOutputWhenEnableOutputSplitIsFalse() + public async Task LogProcessDetailsDoesNotSplitTelemetryOutputWhenEnableOutputSplitIsFalse() { int maxCharlimit = 125000; @@ -2357,14 +2357,14 @@ public async Task LogProcessDetailsDoesNotSplitOutputWhenEnableOutputSplitIsFals TestExecutor component = new TestExecutor(this.mockFixture); component.Logger = this.mockLogger.Object; - await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit, enableOutputSplit: false).ConfigureAwait(false); + await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit, telemetrySplit: false).ConfigureAwait(false); // Should only log ONE event (no splitting) this.mockLogger.Verify(logger => logger.Log(It.IsAny(), It.IsAny(), It.IsAny(), null, null), Times.Once); } [Test] - public async Task LogProcessDetailsDoesNotSplitWhenCombinedOutputIsBelowMaxChars() + public async Task LogProcessDetailsDoesNotSplitTelemetryWhenCombinedOutputIsBelowMaxChars() { // Scenario: // When enableOutputSplit is true BUT combined output is below maxChars, no splitting should occur. @@ -2400,14 +2400,14 @@ public async Task LogProcessDetailsDoesNotSplitWhenCombinedOutputIsBelowMaxChars TestExecutor component = new TestExecutor(this.mockFixture); component.Logger = this.mockLogger.Object; - await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit, enableOutputSplit: false).ConfigureAwait(false); + await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit, telemetrySplit: false).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 LogProcessDetailsSplitsOutputOnlyWhenBothConditionsAreMet() + public async Task LogProcessDetailsSplitsTelemetryOutputOnlyWhenBothConditionsAreMet() { // Scenario: // Splitting should occur ONLY when enableOutputSplit=true AND combined output > maxChars @@ -2450,7 +2450,7 @@ public async Task LogProcessDetailsSplitsOutputOnlyWhenBothConditionsAreMet() TestExecutor component = new TestExecutor(this.mockFixture); component.Logger = this.mockLogger.Object; - await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit, enableOutputSplit: true).ConfigureAwait(false); + await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit, telemetrySplit: true).ConfigureAwait(false); // Verify splitting occurred Assert.AreEqual(2, standardOutputEventCount, "Should create 2 events for standard output chunks"); @@ -2460,7 +2460,7 @@ public async Task LogProcessDetailsSplitsOutputOnlyWhenBothConditionsAreMet() } [Test] - public async Task LogProcessDetailsSplitCapturesAllDataWithoutTruncation() + public async Task LogProcessDetailsSplitTelemetryCapturesAllDataWithoutTruncation() { // Scenario: // When splitting occurs, verify ALL data is captured without any truncation. @@ -2511,7 +2511,7 @@ public async Task LogProcessDetailsSplitCapturesAllDataWithoutTruncation() TestExecutor component = new TestExecutor(this.mockFixture); component.Logger = this.mockLogger.Object; - await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit, enableOutputSplit: true).ConfigureAwait(false); + await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit, telemetrySplit: true).ConfigureAwait(false); // Verify NO truncation occurred Assert.AreEqual(expectedOutput.Length, capturedStandardOutput.Length, "All standard output should be captured"); @@ -2522,7 +2522,7 @@ public async Task LogProcessDetailsSplitCapturesAllDataWithoutTruncation() } [Test] - public async Task LogProcessDetailsSplitIncludesChunkPartNumberInContext() + public async Task LogProcessDetailsSplitTelemetryIncludesChunkPartNumberInContext() { // Scenario: // Verify that split events include chunk part numbers for tracking. @@ -2554,7 +2554,7 @@ public async Task LogProcessDetailsSplitIncludesChunkPartNumberInContext() TestExecutor component = new TestExecutor(this.mockFixture); component.Logger = this.mockLogger.Object; - await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit, enableOutputSplit: true).ConfigureAwait(false); + await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit, telemetrySplit: true).ConfigureAwait(false); // Verify chunk parts are numbered sequentially starting from 1 Assert.AreEqual(2, chunkParts.Count, "Should have 2 chunk parts"); @@ -2564,7 +2564,7 @@ public async Task LogProcessDetailsSplitIncludesChunkPartNumberInContext() } [Test] - public async Task LogProcessDetailsSplitStandardOutputAndErrorSeparately() + public async Task LogProcessDetailsSplitsStandardOutputAndErrorSeparately() { // Scenario: // When standard output and standard error equals maxChars exactly, split output and error separately. @@ -2587,13 +2587,13 @@ public async Task LogProcessDetailsSplitStandardOutputAndErrorSeparately() TestExecutor component = new TestExecutor(this.mockFixture); component.Logger = this.mockLogger.Object; - await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit, enableOutputSplit: true).ConfigureAwait(false); + await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit, telemetrySplit: true).ConfigureAwait(false); this.mockLogger.Verify(logger => logger.Log(It.IsAny(), It.IsAny(), It.IsAny(), null, null), Times.Exactly(2)); } [Test] - public async Task LogProcessDetailsSplitHandlesBoundaryConditionOneCharOverMaxChars() + public async Task LogProcessDetailsSplitTelemetryHandlesBoundaryConditionOneCharOverMaxChars() { // Scenario: // When combined output is just 1 char over maxChars, splitting should occur. @@ -2624,7 +2624,7 @@ public async Task LogProcessDetailsSplitHandlesBoundaryConditionOneCharOverMaxCh TestExecutor component = new TestExecutor(this.mockFixture); component.Logger = this.mockLogger.Object; - await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit, enableOutputSplit: true).ConfigureAwait(false); + await component.LogProcessDetailsAsync(process, new EventContext(Guid.NewGuid()), logToTelemetry: true, logToTelemetryMaxChars: maxCharlimit, telemetrySplit: true).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"); diff --git a/src/VirtualClient/VirtualClient.Core/VirtualClientLoggingExtensions.cs b/src/VirtualClient/VirtualClient.Core/VirtualClientLoggingExtensions.cs index f52aa27ba7..2fd6f043ba 100644 --- a/src/VirtualClient/VirtualClient.Core/VirtualClientLoggingExtensions.cs +++ b/src/VirtualClient/VirtualClient.Core/VirtualClientLoggingExtensions.cs @@ -52,18 +52,18 @@ public static class VirtualClientLoggingExtensions /// The name to use for the log file when writing to the file system. Default = component 'Scenario' parameter value. /// True if any log files generated should be prefixed with timestamps. Default = true. /// True to request the file be uploaded when a content store is defined. - /// - /// When true, splits the standard output and error into multiple telemetry events if they exceed maxChars. + /// + /// When true, splits the standard output and standard error into multiple telemetry events if they exceed maxChars. /// When false, truncates the standard output/error at maxChars (existing behavior). /// public static Task LogProcessDetailsAsync( - this VirtualClientComponent component, IProcessProxy process, EventContext telemetryContext, string toolName = null, IEnumerable results = null, bool logToTelemetry = true, bool logToFile = true, int logToTelemetryMaxChars = 125000, string logFileName = null, bool timestamped = true, bool upload = true, bool enableOutputSplit = false) + this VirtualClientComponent component, IProcessProxy process, EventContext telemetryContext, string toolName = null, IEnumerable results = null, bool logToTelemetry = true, bool logToFile = true, int logToTelemetryMaxChars = 125000, string logFileName = null, bool timestamped = true, bool upload = true, bool telemetrySplit = false) { component.ThrowIfNull(nameof(component)); process.ThrowIfNull(nameof(process)); telemetryContext.ThrowIfNull(nameof(telemetryContext)); - return LogProcessDetailsAsync(component, process.ToProcessDetails(toolName, results), telemetryContext, logToTelemetry, logToFile, logToTelemetryMaxChars, logFileName, timestamped, upload, enableOutputSplit); + return LogProcessDetailsAsync(component, process.ToProcessDetails(toolName, results), telemetryContext, logToTelemetry, logToFile, logToTelemetryMaxChars, logFileName, timestamped, upload, telemetrySplit); } /// @@ -106,7 +106,7 @@ public static async Task LogProcessDetailsAsync(this VirtualClientComponent comp { try { - component.Logger?.LogProcessDetails(processDetails, component.TypeName, telemetryContext, logToTelemetryMaxChars, enableOutputSplit: enableOutputSplit); + component.Logger?.LogProcessDetails(processDetails, component.TypeName, telemetryContext, logToTelemetryMaxChars, telemetrySplit: enableOutputSplit); } catch (Exception exc) { @@ -158,17 +158,17 @@ public static async Task LogProcessDetailsAsync(this VirtualClientComponent comp /// without risking data loss during upload because the message exceeds thresholds. Default = 125,000 chars. In relativity /// there are about 3000 characters in an average single-spaced page of text. /// - /// + /// /// When true, splits the standard output and error into multiple telemetry events if they exceed maxChars. /// When false, truncates the standard output/error at maxChars (existing behavior). /// - internal static void LogProcessDetails(this ILogger logger, ProcessDetails processDetails, string componentType, EventContext telemetryContext, int logToTelemetryMaxChars = 125000, bool enableOutputSplit = false) + internal static void LogProcessDetails(this ILogger logger, ProcessDetails processDetails, string componentType, EventContext telemetryContext, int logToTelemetryMaxChars = 125000, bool telemetrySplit = false) { logger.ThrowIfNull(nameof(logger)); componentType.ThrowIfNullOrWhiteSpace(nameof(componentType)); processDetails.ThrowIfNull(nameof(processDetails)); telemetryContext.ThrowIfNull(nameof(telemetryContext)); - telemetryContext.AddContext(nameof(enableOutputSplit), enableOutputSplit); + telemetryContext.AddContext(nameof(telemetrySplit), telemetrySplit); try { @@ -187,7 +187,7 @@ internal static void LogProcessDetails(this ILogger logger, ProcessDetails proce !string.IsNullOrWhiteSpace(processDetails.ToolName) ? $"{componentType}.{processDetails.ToolName}" : componentType, string.Empty); - if (enableOutputSplit && (processDetails.StandardOutput.Length + processDetails.StandardError.Length > logToTelemetryMaxChars)) + if (telemetrySplit && (processDetails.StandardOutput.Length + processDetails.StandardError.Length > logToTelemetryMaxChars)) { // Handle splitting standard output and error if enabled and necessary List standardOutputChunks = VirtualClientLoggingExtensions.SplitString(processDetails.StandardOutput, logToTelemetryMaxChars); From 1c36d9f003e4add4723b0ea4f948f15ea30e9066 Mon Sep 17 00:00:00 2001 From: nchapagain001 <165215502+nchapagain001@users.noreply.github.com> Date: Wed, 22 Oct 2025 22:35:36 -0700 Subject: [PATCH 6/6] foo --- .../VirtualClient.Monitors/ExecuteCommandMonitor.cs | 13 ++++++++++++- 1 file changed, 12 insertions(+), 1 deletion(-) diff --git a/src/VirtualClient/VirtualClient.Monitors/ExecuteCommandMonitor.cs b/src/VirtualClient/VirtualClient.Monitors/ExecuteCommandMonitor.cs index 4680120ba0..9aec1a5832 100644 --- a/src/VirtualClient/VirtualClient.Monitors/ExecuteCommandMonitor.cs +++ b/src/VirtualClient/VirtualClient.Monitors/ExecuteCommandMonitor.cs @@ -115,6 +115,17 @@ public string MonitorEventType } } + /// + /// Parameter defines Telemetry Splitting (true/false). Default = false. + /// + public bool TelemetrySplit + { + get + { + return this.Parameters.GetValue(nameof(this.TelemetrySplit), false); + } + } + /// /// A policy that defines how the component will retry when it experiences transient issues. /// @@ -252,7 +263,7 @@ protected async Task ExecuteCommandAsync(EventContext telemetryContext, Cancella if (!cancellationToken.IsCancellationRequested) { - await this.LogProcessDetailsAsync(process, telemetryContext, toolName: this.LogFolderName, logFileName: this.LogFileName); + await this.LogProcessDetailsAsync(process, telemetryContext, toolName: this.LogFolderName, logFileName: this.LogFileName, telemetrySplit: this.TelemetrySplit); process.ThrowIfMonitorFailed(); this.CaptureEventInformation(process, telemetryContext); }