From e42776b00f9674d2e85eb91ff6f6837d430b36bd Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Thu, 12 Dec 2024 15:28:29 +0530 Subject: [PATCH 01/51] added tracing --- src/Agent.Sdk/ProcessInvoker.cs | 5 ++++ src/Agent.Worker/ExecutionContext.cs | 4 ++++ src/Agent.Worker/Handlers/NodeHandler.cs | 6 +++++ src/Agent.Worker/ResourceMetricsManager.cs | 28 ++++++++++++++++++++++ src/Agent.Worker/TaskRunner.cs | 2 ++ 5 files changed, 45 insertions(+) diff --git a/src/Agent.Sdk/ProcessInvoker.cs b/src/Agent.Sdk/ProcessInvoker.cs index 3a9d32e6eb..81886657e5 100644 --- a/src/Agent.Sdk/ProcessInvoker.cs +++ b/src/Agent.Sdk/ProcessInvoker.cs @@ -332,10 +332,12 @@ public async Task ExecuteAsync( AsyncManualResetEvent afterCancelKillProcessTreeAttemptSignal = new AsyncManualResetEvent(); using (var registration = cancellationToken.Register(async () => { + Trace.Info("##DEBUG_SB: Cancellation requested, attempting to cancel and kill process tree."); await CancelAndKillProcessTree(killProcessOnCancel); // signal to ensure we exit the loop after we attempt to cancel and kill the process tree (which is best effort) afterCancelKillProcessTreeAttemptSignal.Set(); + Trace.Info("##DEBUG_SB: Cancellation requested, process tree killed."); })) { Trace.Info($"Process started with process id {_proc.Id}, waiting for process exit."); @@ -460,6 +462,9 @@ internal protected virtual async Task CancelAndKillProcessTree(bool killProcessO bool gracefulShoutdown = TryUseGracefulShutdown && !killProcessOnCancel; ArgUtil.NotNull(_proc, nameof(_proc)); + + Trace.Info($"##DEBUG_SB: Cancel and kill process tree for process {_proc.Id}."); + if (!killProcessOnCancel) { bool sigint_succeed = await SendSIGINT(SigintTimeout); diff --git a/src/Agent.Worker/ExecutionContext.cs b/src/Agent.Worker/ExecutionContext.cs index d38702e216..ca1281858f 100644 --- a/src/Agent.Worker/ExecutionContext.cs +++ b/src/Agent.Worker/ExecutionContext.cs @@ -212,11 +212,15 @@ public void ForceTaskComplete() Trace.Info("Force finish current task in 5 sec."); Task.Run(async () => { + Trace.Info("##DEBUG_SB: Force finish task delay 5 sec."); await Task.Delay(TimeSpan.FromSeconds(5), ForceCompleteCancellationToken); if (!ForceCompleteCancellationToken.IsCancellationRequested) { + Trace.Info("##DEBUG_SB: if block trysetresult"); _forceCompleted?.TrySetResult(1); + Trace.Info("##DEBUG_SB: if block trysetresult done"); } + Trace.Info("##DEBUG_SB: Force finish task delay 5 sec. Done."); }); } diff --git a/src/Agent.Worker/Handlers/NodeHandler.cs b/src/Agent.Worker/Handlers/NodeHandler.cs index b96712c559..0326c4c0da 100644 --- a/src/Agent.Worker/Handlers/NodeHandler.cs +++ b/src/Agent.Worker/Handlers/NodeHandler.cs @@ -256,21 +256,27 @@ public async Task RunAsync() cancellationToken: ExecutionContext.CancellationToken); // Wait for either the node exit or force finish through ##vso command + Trace.Info("##DEBUG_SB: Waiting for node process to exit."); await System.Threading.Tasks.Task.WhenAny(step, ExecutionContext.ForceCompleted); + Trace.Info("##DEBUG_SB: Node process has exited."); if (ExecutionContext.ForceCompleted.IsCompleted) { + Trace.Info("##DEBUG_SB: The task was marked as \"done\", but the process has not closed after 5 seconds. Treating the task as complete."); ExecutionContext.Debug("The task was marked as \"done\", but the process has not closed after 5 seconds. Treating the task as complete."); } else { + Trace.Info("##DEBUG_SB: force completed else block"); await step; + Trace.Info("##DEBUG_SB: force completed else block step has completed"); } } catch (ProcessExitCodeException ex) { if (enableResourceUtilizationWarnings && ex.ExitCode == 137) { + Trace.Error("##DEBUG_SB: The task was terminated because it consumed too much memory."); ExecutionContext.Error(StringUtil.Loc("AgentOutOfMemoryFailure")); } diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index e56f9cb35e..39469cfae6 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -181,6 +181,7 @@ await Task.Run(() => } if (PlatformUtil.RunningOnMacOS) { + Trace.Info("##DEBUG_SB: CPU info - Getting CPU usage on MacOS"); using var processInvoker = HostContext.CreateService(); List outputs = new List(); @@ -196,6 +197,7 @@ await Task.Run(() => var filePath = "/bin/bash"; var arguments = "-c \"top -l 2 -o cpu | grep ^CPU\""; + Trace.Info($"##DEBUG_SB: CPU info - Executing {filePath} {arguments}"); await processInvoker.ExecuteAsync( workingDirectory: string.Empty, fileName: filePath, @@ -291,6 +293,7 @@ await Task.Run(() => // but unfortunately it returns values in pages and has no built-in arguments for custom output // so we need to parse and cast the output manually + Trace.Info("##DEBUG_SB: Getting memory info on MacOS"); using var processInvoker = HostContext.CreateService(); List outputs = new List(); @@ -305,6 +308,8 @@ await Task.Run(() => }; var filePath = "vm_stat"; + Trace.Info($"##DEBUG_SB: Memory info - Executing {filePath}"); + await processInvoker.ExecuteAsync( workingDirectory: string.Empty, fileName: filePath, @@ -389,6 +394,7 @@ private async Task GetMemoryInfoStringAsync(CancellationToken cancellati #region MonitorLoops public async Task RunDebugResourceMonitorAsync() { + Trace.Info("##DEBUG_SB: Starting debug resource monitor"); while (!_context.CancellationToken.IsCancellationRequested) { using var timeoutTokenSource = new CancellationTokenSource(); @@ -398,17 +404,22 @@ public async Task RunDebugResourceMonitorAsync() _context.CancellationToken, timeoutTokenSource.Token); + Trace.Info("##DEBUG_SB: Debug Resource Monitor"); _context.Debug(StringUtil.Loc("ResourceMonitorAgentEnvironmentResource", GetDiskInfoString(), await GetMemoryInfoStringAsync(linkedTokenSource.Token), await GetCpuInfoStringAsync(linkedTokenSource.Token))); + Trace.Info($"##DEBUG_SB: Waiting for {ACTIVE_MODE_INTERVAL} ms"); await Task.Delay(ACTIVE_MODE_INTERVAL, _context.CancellationToken); + Trace.Info($"##DEBUG_SB: Done waiting for {ACTIVE_MODE_INTERVAL} ms"); } + Trace.Info("##DEBUG_SB: Exiting debug resource monitor"); } public async Task RunDiskSpaceUtilizationMonitorAsync() { + Trace.Info("##DEBUG_SB: Starting disk space utilization monitor"); while (!_context.CancellationToken.IsCancellationRequested) { try @@ -435,12 +446,16 @@ public async Task RunDiskSpaceUtilizationMonitorAsync() break; } + Trace.Info($"##DEBUG_SB: Disk Space Utilization - Waiting for {WARNING_MESSAGE_INTERVAL} ms"); await Task.Delay(WARNING_MESSAGE_INTERVAL, _context.CancellationToken); + Trace.Info($"##DEBUG_SB: Disk Space Utilization - Done waiting for {WARNING_MESSAGE_INTERVAL} ms"); } + Trace.Info("##DEBUG_SB: Exiting disk space utilization monitor"); } public async Task RunMemoryUtilizationMonitorAsync() { + Trace.Info("##DEBUG_SB: Starting memory utilization monitor"); while (!_context.CancellationToken.IsCancellationRequested) { using var timeoutTokenSource = new CancellationTokenSource(); @@ -450,6 +465,9 @@ public async Task RunMemoryUtilizationMonitorAsync() _context.CancellationToken, timeoutTokenSource.Token); + // display cancellation token and properties + Trace.Info($"##DEBUG_SB: Memory Utilization - CancellationToken: {linkedTokenSource.Token}"); + try { await GetMemoryInfoAsync(linkedTokenSource.Token); @@ -472,12 +490,17 @@ public async Task RunMemoryUtilizationMonitorAsync() break; } + Trace.Info($"##DEBUG_SB: Memory Utilization - Waiting for {WARNING_MESSAGE_INTERVAL} ms"); await Task.Delay(WARNING_MESSAGE_INTERVAL, _context.CancellationToken); + Trace.Info($"##DEBUG_SB: Memory Utilization - Done waiting for {WARNING_MESSAGE_INTERVAL} ms"); } + + Trace.Info("##DEBUG_SB: Exiting memory utilization monitor"); } public async Task RunCpuUtilizationMonitorAsync(string taskId) { + Trace.Info("##DEBUG_SB: Starting CPU utilization monitor"); while (!_context.CancellationToken.IsCancellationRequested) { using var timeoutTokenSource = new CancellationTokenSource(); @@ -487,6 +510,8 @@ public async Task RunCpuUtilizationMonitorAsync(string taskId) _context.CancellationToken, timeoutTokenSource.Token); + Trace.Info($"##DEBUG_SB: CPU Utilization - CancellationToken: {linkedTokenSource.Token}"); + try { await GetCpuInfoAsync(linkedTokenSource.Token); @@ -508,8 +533,11 @@ public async Task RunCpuUtilizationMonitorAsync(string taskId) break; } + Trace.Info($"##DEBUG_SB: CPU Utilization - Waiting for {WARNING_MESSAGE_INTERVAL} ms"); await Task.Delay(WARNING_MESSAGE_INTERVAL, _context.CancellationToken); + Trace.Info($"##DEBUG_SB: CPU Utilization - Done waiting for {WARNING_MESSAGE_INTERVAL} ms"); } + Trace.Info("##DEBUG_SB: Exiting CPU utilization monitor"); } #endregion } diff --git a/src/Agent.Worker/TaskRunner.cs b/src/Agent.Worker/TaskRunner.cs index 8d50526c4c..4cfee6d9b2 100644 --- a/src/Agent.Worker/TaskRunner.cs +++ b/src/Agent.Worker/TaskRunner.cs @@ -419,6 +419,8 @@ private async Task RunAsyncInternal() if (enableResourceUtilizationWarnings) { + // add tracing statement to indicate that resource utilization warnings are enabled + Trace.Info("##DEBUG_SB: Resource utilization warnings are enabled."); _ = resourceDiagnosticManager.RunMemoryUtilizationMonitorAsync(); _ = resourceDiagnosticManager.RunDiskSpaceUtilizationMonitorAsync(); _ = resourceDiagnosticManager.RunCpuUtilizationMonitorAsync(Task.Reference.Id.ToString()); From 19da14dfc1e725eaf8f3eb4e826327d267f6f12b Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Fri, 13 Dec 2024 15:21:39 +0530 Subject: [PATCH 02/51] added more tracing --- src/Agent.Worker/ExecutionContext.cs | 8 ++++ src/Agent.Worker/ResourceMetricsManager.cs | 39 ++++++++-------- src/Agent.Worker/RetryHelper.cs | 2 + src/Agent.Worker/StepsRunner.cs | 52 ++++++++++++++++++++++ src/Agent.Worker/TaskCommandExtension.cs | 1 + 5 files changed, 83 insertions(+), 19 deletions(-) diff --git a/src/Agent.Worker/ExecutionContext.cs b/src/Agent.Worker/ExecutionContext.cs index ca1281858f..9c75f561f5 100644 --- a/src/Agent.Worker/ExecutionContext.cs +++ b/src/Agent.Worker/ExecutionContext.cs @@ -90,6 +90,11 @@ public interface IExecutionContext : IAgentService, IKnobValueContext void CancelForceTaskCompletion(); void EmitHostNode20FallbackTelemetry(bool node20ResultsInGlibCErrorHost); void PublishTaskRunnerTelemetry(Dictionary taskRunnerData); + + /// TO-DO: + /// Disposes the execution context. + /// + // void Dispose(); } public sealed class ExecutionContext : AgentService, IExecutionContext, IDisposable @@ -337,7 +342,9 @@ public TaskResult Complete(TaskResult? result = null, string currentOperation = _record.ResultCode = resultCode ?? _record.ResultCode; _record.FinishTime = DateTime.UtcNow; _record.PercentComplete = 100; + Trace.Info($"##DEBUG_SB: BEFORE Task result: '{_record.Result}'."); _record.Result = _record.Result ?? TaskResult.Succeeded; + Trace.Info($"##DEBUG_SB: AFTER Task result: '{_record.Result}'."); _record.State = TimelineRecordState.Completed; _jobServerQueue.QueueTimelineRecordUpdate(_mainTimelineId, _record); @@ -981,6 +988,7 @@ public void PublishTaskRunnerTelemetry(Dictionary taskRunnerData public void Dispose() { + Trace.Info("##DEBUG_SB: ExecutionContext.Dispose() was called"); _cancellationTokenSource?.Dispose(); _forceCompleteCancellationTokenSource?.Dispose(); diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index 39469cfae6..d837945f59 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -111,7 +111,7 @@ private void PublishTelemetry(string message, string taskId) #endregion #region MetricMethods - private async Task GetCpuInfoAsync(CancellationToken cancellationToken) + private async Task GetCpuInfoAsync(CancellationToken cancellationToken, string source) { if (_cpuInfo.Updated >= DateTime.Now - TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)) { @@ -181,7 +181,7 @@ await Task.Run(() => } if (PlatformUtil.RunningOnMacOS) { - Trace.Info("##DEBUG_SB: CPU info - Getting CPU usage on MacOS"); + Trace.Info($"##DEBUG_SB: CPU info - Getting CPU usage on MacOS from source: {source}"); using var processInvoker = HostContext.CreateService(); List outputs = new List(); @@ -197,7 +197,7 @@ await Task.Run(() => var filePath = "/bin/bash"; var arguments = "-c \"top -l 2 -o cpu | grep ^CPU\""; - Trace.Info($"##DEBUG_SB: CPU info - Executing {filePath} {arguments}"); + Trace.Info($"##DEBUG_SB: CPU info - Executing {filePath} {arguments}; source: {source}"); await processInvoker.ExecuteAsync( workingDirectory: string.Empty, fileName: filePath, @@ -219,8 +219,9 @@ await processInvoker.ExecuteAsync( } } - private void GetDiskInfo() + private void GetDiskInfo(string source) { + Trace.Info($"##DEBUG_SB: Getting disk info from source: {source}"); if (_diskInfo.Updated >= DateTime.Now - TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)) { return; @@ -238,7 +239,7 @@ private void GetDiskInfo() } } - private async Task GetMemoryInfoAsync(CancellationToken cancellationToken) + private async Task GetMemoryInfoAsync(CancellationToken cancellationToken, string source) { if (_memoryInfo.Updated >= DateTime.Now - TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)) { @@ -293,7 +294,7 @@ await Task.Run(() => // but unfortunately it returns values in pages and has no built-in arguments for custom output // so we need to parse and cast the output manually - Trace.Info("##DEBUG_SB: Getting memory info on MacOS"); + Trace.Info($"##DEBUG_SB: Getting memory info on MacOS from source: {source}"); using var processInvoker = HostContext.CreateService(); List outputs = new List(); @@ -308,7 +309,7 @@ await Task.Run(() => }; var filePath = "vm_stat"; - Trace.Info($"##DEBUG_SB: Memory info - Executing {filePath}"); + Trace.Info($"##DEBUG_SB: Memory info - Executing {filePath}; statement source: {source}"); await processInvoker.ExecuteAsync( workingDirectory: string.Empty, @@ -343,11 +344,11 @@ await processInvoker.ExecuteAsync( #endregion #region StringMethods - private async Task GetCpuInfoStringAsync(CancellationToken cancellationToken) + private async Task GetCpuInfoStringAsync(CancellationToken cancellationToken, string source) { try { - await GetCpuInfoAsync(cancellationToken); + await GetCpuInfoAsync(cancellationToken, source); return StringUtil.Loc("ResourceMonitorCPUInfo", $"{_cpuInfo.Usage:0.00}"); } @@ -357,11 +358,11 @@ private async Task GetCpuInfoStringAsync(CancellationToken cancellationT } } - private string GetDiskInfoString() + private string GetDiskInfoString(string source) { try { - GetDiskInfo(); + GetDiskInfo(source); return StringUtil.Loc("ResourceMonitorDiskInfo", _diskInfo.VolumeRoot, @@ -374,11 +375,11 @@ private string GetDiskInfoString() } } - private async Task GetMemoryInfoStringAsync(CancellationToken cancellationToken) + private async Task GetMemoryInfoStringAsync(CancellationToken cancellationToken, string source) { try { - await GetMemoryInfoAsync(cancellationToken); + await GetMemoryInfoAsync(cancellationToken, source); return StringUtil.Loc("ResourceMonitorMemoryInfo", $"{_memoryInfo.UsedMemoryMB:0.00}", @@ -406,9 +407,9 @@ public async Task RunDebugResourceMonitorAsync() Trace.Info("##DEBUG_SB: Debug Resource Monitor"); _context.Debug(StringUtil.Loc("ResourceMonitorAgentEnvironmentResource", - GetDiskInfoString(), - await GetMemoryInfoStringAsync(linkedTokenSource.Token), - await GetCpuInfoStringAsync(linkedTokenSource.Token))); + GetDiskInfoString("Debug Resource Monitor"), + await GetMemoryInfoStringAsync(linkedTokenSource.Token, "Debug Resource Monitor"), + await GetCpuInfoStringAsync(linkedTokenSource.Token, "Debug Resource Monitor"))); Trace.Info($"##DEBUG_SB: Waiting for {ACTIVE_MODE_INTERVAL} ms"); await Task.Delay(ACTIVE_MODE_INTERVAL, _context.CancellationToken); @@ -424,7 +425,7 @@ public async Task RunDiskSpaceUtilizationMonitorAsync() { try { - GetDiskInfo(); + GetDiskInfo("Resource Utilization Warnings"); var freeDiskSpacePercentage = Math.Round(((_diskInfo.FreeDiskSpaceMB / (double)_diskInfo.TotalDiskSpaceMB) * 100.0), 2); var usedDiskSpacePercentage = 100.0 - freeDiskSpacePercentage; @@ -470,7 +471,7 @@ public async Task RunMemoryUtilizationMonitorAsync() try { - await GetMemoryInfoAsync(linkedTokenSource.Token); + await GetMemoryInfoAsync(linkedTokenSource.Token, "Resource Utilization Warnings"); var usedMemoryPercentage = Math.Round(((_memoryInfo.UsedMemoryMB / (double)_memoryInfo.TotalMemoryMB) * 100.0), 2); @@ -514,7 +515,7 @@ public async Task RunCpuUtilizationMonitorAsync(string taskId) try { - await GetCpuInfoAsync(linkedTokenSource.Token); + await GetCpuInfoAsync(linkedTokenSource.Token, "Resource Utilization Warnings"); if (_cpuInfo.Usage >= CPU_UTILIZATION_PERCENTAGE_THRESHOLD) { diff --git a/src/Agent.Worker/RetryHelper.cs b/src/Agent.Worker/RetryHelper.cs index 9e3aabe1b0..2208eae0fc 100644 --- a/src/Agent.Worker/RetryHelper.cs +++ b/src/Agent.Worker/RetryHelper.cs @@ -81,7 +81,9 @@ public async Task RetryStep(Func action, Func timeDelayInterval) if (retryCounter > 0) { //ReInitialize _forceCompleted and _forceCompleteCancellationTokenSource + Trace.Info("##DEBUG_SB: Calling ReInitializeForceCompletedin RetryHelper.RetryStep"); ExecutionContext.ReInitializeForceCompleted(); + Trace.Info("##DEBUG_SB: Called ReInitializeForceCompletedin RetryHelper.RetryStep"); } Debug($"Invoking Method: {action.Method}. Attempt count: {retryCounter}"); diff --git a/src/Agent.Worker/StepsRunner.cs b/src/Agent.Worker/StepsRunner.cs index b9bee6eb81..a6ad777a92 100644 --- a/src/Agent.Worker/StepsRunner.cs +++ b/src/Agent.Worker/StepsRunner.cs @@ -213,7 +213,10 @@ public async Task RunAsync(IExecutionContext jobContext, IList steps) else { // Run the step. + Trace.Info("##DEBUG_SB: Running the step in StepsRunner."); await RunStepAsync(step, jobContext.CancellationToken); + Trace.Info($"##DEBUG_SB: Step result: {step.ExecutionContext.Result}"); + Trace.Info("##DEBUG_SB: Finished running the step in StepsRunner."); } } finally @@ -314,6 +317,7 @@ private async Task RunStepAsync(IStep step, CancellationToken jobCancellationTok step.ExecutionContext.Error(StringUtil.Loc("StepTimedOut")); // if the step already canceled, don't set it to failed. + Trace.Info($"##DEBUG_SB: check 1 step.ExecutionContext.CommandResult: {step.ExecutionContext.CommandResult}"); step.ExecutionContext.CommandResult = TaskResultUtil.MergeTaskResults(step.ExecutionContext.CommandResult, TaskResult.Failed); } else if (AgentKnobs.FailJobWhenAgentDies.GetValue(step.ExecutionContext).AsBoolean() && @@ -324,6 +328,7 @@ private async Task RunStepAsync(IStep step, CancellationToken jobCancellationTok step.ExecutionContext.Error(ex); // if the step already canceled, don't set it to failed. + Trace.Info($"##DEBUG_SB: check 2 step.ExecutionContext.CommandResult: {step.ExecutionContext.CommandResult}"); step.ExecutionContext.CommandResult = TaskResultUtil.MergeTaskResults(step.ExecutionContext.CommandResult, TaskResult.Failed); } else @@ -333,6 +338,7 @@ private async Task RunStepAsync(IStep step, CancellationToken jobCancellationTok step.ExecutionContext.Error(ex); // if the step already failed, don't set it to canceled. + Trace.Info($"##DEBUG_SB: check 3 step.ExecutionContext.CommandResult: {step.ExecutionContext.CommandResult}"); step.ExecutionContext.CommandResult = TaskResultUtil.MergeTaskResults(step.ExecutionContext.CommandResult, TaskResult.Canceled); } } @@ -343,6 +349,7 @@ private async Task RunStepAsync(IStep step, CancellationToken jobCancellationTok step.ExecutionContext.Error(ex); // if the step already canceled, don't set it to failed. + Trace.Info($"##DEBUG_SB: check 4 step.ExecutionContext.CommandResult: {step.ExecutionContext.CommandResult}"); step.ExecutionContext.CommandResult = TaskResultUtil.MergeTaskResults(step.ExecutionContext.CommandResult, TaskResult.Failed); } } @@ -350,6 +357,8 @@ private async Task RunStepAsync(IStep step, CancellationToken jobCancellationTok // Merge executioncontext result with command result if (step.ExecutionContext.CommandResult != null) { + Trace.Info($"##DEBUG_SB: Merging step result with command result: {step.ExecutionContext.CommandResult.Value}"); + Trace.Info($"##DEBUG_SB: Before merge, step result: {step.ExecutionContext.Result}"); step.ExecutionContext.Result = TaskResultUtil.MergeTaskResults(step.ExecutionContext.Result, step.ExecutionContext.CommandResult.Value); } @@ -361,12 +370,55 @@ private async Task RunStepAsync(IStep step, CancellationToken jobCancellationTok } else { + // display status of TaskResult + try: + Trace.Info($'##DEBUG_SB: TaskResult.Succeeded: {TaskResult.Succeeded}'); + catch (Exception ex) + { + Trace.Info($'##DEBUG_SB: Could not display TaskResult.Succeeded: {ex.Message}'); + } + try: + Trace.Info($'##DEBUG_SB: TaskResult.SucceededWithIssues: {TaskResult.SucceededWithIssues}'); + catch (Exception ex) + { + Trace.Info($'##DEBUG_SB: Could not display TaskResult.SucceededWithIssues: {ex.Message}'); + } + try: + Trace.Info($'##DEBUG_SB: TaskResult.Failed: {TaskResult.Failed}'); + catch (Exception ex) + { + Trace.Info($'##DEBUG_SB: Could not display TaskResult.Failed: {ex.Message}'); + } + try: + Trace.Info($'##DEBUG_SB: TaskResult.Canceled: {TaskResult.Canceled}'); + catch (Exception ex) + { + Trace.Info($'##DEBUG_SB: Could not display TaskResult.Canceled: {ex.Message}'); + } + try: + Trace.Info($'##DEBUG_SB: TaskResult.Skipped: {TaskResult.Skipped}'); + catch (Exception ex) + { + Trace.Info($'##DEBUG_SB: Could not display TaskResult.Skipped: {ex.Message}'); + } + try: + Trace.Info($'##DEBUG_SB: TaskResult.Abandoned: {TaskResult.Abandoned}'); + catch (Exception ex) + { + Trace.Info($'##DEBUG_SB: Could not display TaskResult.Abandoned: {ex.Message}'); + } + + Trace.Info($"Step result: {step.ExecutionContext.Result}"); } // Complete the step context. + Trace.Info("##DEBUG_SB: Finishing step in RunStepAsync."); + Trace.Info($"##DEBUG_SB: check1 Step result: {step.ExecutionContext.Result}"); step.ExecutionContext.Section(StringUtil.Loc("StepFinishing", step.DisplayName)); + Trace.Info($"##DEBUG_SB: check2 Step result: {step.ExecutionContext.Result}"); step.ExecutionContext.Complete(); + Trace.Info($"##DEBUG_SB: check3 Step result: {step.ExecutionContext.Result}"); } private async Task SwitchToUtf8Codepage(IStep step) diff --git a/src/Agent.Worker/TaskCommandExtension.cs b/src/Agent.Worker/TaskCommandExtension.cs index 38e949941a..8ab45817a1 100644 --- a/src/Agent.Worker/TaskCommandExtension.cs +++ b/src/Agent.Worker/TaskCommandExtension.cs @@ -529,6 +529,7 @@ public void Execute(IExecutionContext context, Command command) !String.IsNullOrEmpty(doneText) && StringUtil.ConvertToBoolean(doneText)) { + Trace.Info("##DEBUG_SB: Calling ForceTaskComplete from TaskCompleteCommand"); context.ForceTaskComplete(); } } From 46f65fc95ab79a9238458fd7683437fbf9dd6120 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Fri, 13 Dec 2024 15:33:08 +0530 Subject: [PATCH 03/51] fixed exception handling --- src/Agent.Worker/StepsRunner.cs | 48 ++++++++++++++++++++------------- 1 file changed, 30 insertions(+), 18 deletions(-) diff --git a/src/Agent.Worker/StepsRunner.cs b/src/Agent.Worker/StepsRunner.cs index a6ad777a92..fec9264aaf 100644 --- a/src/Agent.Worker/StepsRunner.cs +++ b/src/Agent.Worker/StepsRunner.cs @@ -371,41 +371,53 @@ private async Task RunStepAsync(IStep step, CancellationToken jobCancellationTok else { // display status of TaskResult - try: - Trace.Info($'##DEBUG_SB: TaskResult.Succeeded: {TaskResult.Succeeded}'); + try + { + Trace.Info($"##DEBUG_SB: TaskResult.Succeeded: {TaskResult.Succeeded}"); + } catch (Exception ex) { - Trace.Info($'##DEBUG_SB: Could not display TaskResult.Succeeded: {ex.Message}'); + Trace.Info($"##DEBUG_SB: Could not display TaskResult.Succeeded: {ex.Message}"); + } + try + { + Trace.Info($"##DEBUG_SB: TaskResult.SucceededWithIssues: {TaskResult.SucceededWithIssues}"); } - try: - Trace.Info($'##DEBUG_SB: TaskResult.SucceededWithIssues: {TaskResult.SucceededWithIssues}'); catch (Exception ex) { - Trace.Info($'##DEBUG_SB: Could not display TaskResult.SucceededWithIssues: {ex.Message}'); + Trace.Info($"##DEBUG_SB: Could not display TaskResult.SucceededWithIssues: {ex.Message}"); + } + try + { + Trace.Info($"##DEBUG_SB: TaskResult.Failed: {TaskResult.Failed}"); } - try: - Trace.Info($'##DEBUG_SB: TaskResult.Failed: {TaskResult.Failed}'); catch (Exception ex) { - Trace.Info($'##DEBUG_SB: Could not display TaskResult.Failed: {ex.Message}'); + Trace.Info($"##DEBUG_SB: Could not display TaskResult.Failed: {ex.Message}"); + } + try + { + Trace.Info($"##DEBUG_SB: TaskResult.Canceled: {TaskResult.Canceled}"); } - try: - Trace.Info($'##DEBUG_SB: TaskResult.Canceled: {TaskResult.Canceled}'); catch (Exception ex) { - Trace.Info($'##DEBUG_SB: Could not display TaskResult.Canceled: {ex.Message}'); + Trace.Info($"##DEBUG_SB: Could not display TaskResult.Canceled: {ex.Message}"); + } + try + { + Trace.Info($"##DEBUG_SB: TaskResult.Skipped: {TaskResult.Skipped}"); } - try: - Trace.Info($'##DEBUG_SB: TaskResult.Skipped: {TaskResult.Skipped}'); catch (Exception ex) { - Trace.Info($'##DEBUG_SB: Could not display TaskResult.Skipped: {ex.Message}'); + Trace.Info($"##DEBUG_SB: Could not display TaskResult.Skipped: {ex.Message}"); + } + try + { + Trace.Info($"##DEBUG_SB: TaskResult.Abandoned: {TaskResult.Abandoned}"); } - try: - Trace.Info($'##DEBUG_SB: TaskResult.Abandoned: {TaskResult.Abandoned}'); catch (Exception ex) { - Trace.Info($'##DEBUG_SB: Could not display TaskResult.Abandoned: {ex.Message}'); + Trace.Info($"##DEBUG_SB: Could not display TaskResult.Abandoned: {ex.Message}"); } From 1876a777d32e25cf35b98945b3efb5ce66ca0bf5 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Fri, 13 Dec 2024 17:47:13 +0530 Subject: [PATCH 04/51] fixed compilation errors --- src/Agent.Worker/ResourceMetricsManager.cs | 34 +++++++++++----------- src/Agent.Worker/RetryHelper.cs | 4 +-- src/Agent.Worker/TaskCommandExtension.cs | 2 +- 3 files changed, 20 insertions(+), 20 deletions(-) diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index d837945f59..a22804c7da 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -111,7 +111,7 @@ private void PublishTelemetry(string message, string taskId) #endregion #region MetricMethods - private async Task GetCpuInfoAsync(CancellationToken cancellationToken, string source) + private async Task GetCpuInfoAsync(CancellationToken cancellationToken) { if (_cpuInfo.Updated >= DateTime.Now - TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)) { @@ -181,7 +181,7 @@ await Task.Run(() => } if (PlatformUtil.RunningOnMacOS) { - Trace.Info($"##DEBUG_SB: CPU info - Getting CPU usage on MacOS from source: {source}"); + Trace.Info($"##DEBUG_SB: CPU info - Getting CPU usage on MacOS from source: "); using var processInvoker = HostContext.CreateService(); List outputs = new List(); @@ -197,7 +197,7 @@ await Task.Run(() => var filePath = "/bin/bash"; var arguments = "-c \"top -l 2 -o cpu | grep ^CPU\""; - Trace.Info($"##DEBUG_SB: CPU info - Executing {filePath} {arguments}; source: {source}"); + Trace.Info($"##DEBUG_SB: CPU info - Executing {filePath} {arguments}; source: "); await processInvoker.ExecuteAsync( workingDirectory: string.Empty, fileName: filePath, @@ -219,9 +219,9 @@ await processInvoker.ExecuteAsync( } } - private void GetDiskInfo(string source) + private void GetDiskInfo() { - Trace.Info($"##DEBUG_SB: Getting disk info from source: {source}"); + Trace.Info($"##DEBUG_SB: Getting disk info from source: "); if (_diskInfo.Updated >= DateTime.Now - TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)) { return; @@ -239,7 +239,7 @@ private void GetDiskInfo(string source) } } - private async Task GetMemoryInfoAsync(CancellationToken cancellationToken, string source) + private async Task GetMemoryInfoAsync(CancellationToken cancellationToken) { if (_memoryInfo.Updated >= DateTime.Now - TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)) { @@ -294,7 +294,7 @@ await Task.Run(() => // but unfortunately it returns values in pages and has no built-in arguments for custom output // so we need to parse and cast the output manually - Trace.Info($"##DEBUG_SB: Getting memory info on MacOS from source: {source}"); + Trace.Info($"##DEBUG_SB: Getting memory info on MacOS from source: "); using var processInvoker = HostContext.CreateService(); List outputs = new List(); @@ -309,7 +309,7 @@ await Task.Run(() => }; var filePath = "vm_stat"; - Trace.Info($"##DEBUG_SB: Memory info - Executing {filePath}; statement source: {source}"); + Trace.Info($"##DEBUG_SB: Memory info - Executing {filePath}; statement source: "); await processInvoker.ExecuteAsync( workingDirectory: string.Empty, @@ -344,7 +344,7 @@ await processInvoker.ExecuteAsync( #endregion #region StringMethods - private async Task GetCpuInfoStringAsync(CancellationToken cancellationToken, string source) + private async Task GetCpuInfoStringAsync(CancellationToken cancellationToken) { try { @@ -358,7 +358,7 @@ private async Task GetCpuInfoStringAsync(CancellationToken cancellationT } } - private string GetDiskInfoString(string source) + private string GetDiskInfoString() { try { @@ -375,7 +375,7 @@ private string GetDiskInfoString(string source) } } - private async Task GetMemoryInfoStringAsync(CancellationToken cancellationToken, string source) + private async Task GetMemoryInfoStringAsync(CancellationToken cancellationToken) { try { @@ -407,9 +407,9 @@ public async Task RunDebugResourceMonitorAsync() Trace.Info("##DEBUG_SB: Debug Resource Monitor"); _context.Debug(StringUtil.Loc("ResourceMonitorAgentEnvironmentResource", - GetDiskInfoString("Debug Resource Monitor"), - await GetMemoryInfoStringAsync(linkedTokenSource.Token, "Debug Resource Monitor"), - await GetCpuInfoStringAsync(linkedTokenSource.Token, "Debug Resource Monitor"))); + GetDiskInfoString(), + await GetMemoryInfoStringAsync(linkedTokenSource.Token), + await GetCpuInfoStringAsync(linkedTokenSource.Token))); Trace.Info($"##DEBUG_SB: Waiting for {ACTIVE_MODE_INTERVAL} ms"); await Task.Delay(ACTIVE_MODE_INTERVAL, _context.CancellationToken); @@ -425,7 +425,7 @@ public async Task RunDiskSpaceUtilizationMonitorAsync() { try { - GetDiskInfo("Resource Utilization Warnings"); + GetDiskInfo(); var freeDiskSpacePercentage = Math.Round(((_diskInfo.FreeDiskSpaceMB / (double)_diskInfo.TotalDiskSpaceMB) * 100.0), 2); var usedDiskSpacePercentage = 100.0 - freeDiskSpacePercentage; @@ -471,7 +471,7 @@ public async Task RunMemoryUtilizationMonitorAsync() try { - await GetMemoryInfoAsync(linkedTokenSource.Token, "Resource Utilization Warnings"); + await GetMemoryInfoAsync(linkedTokenSource.Token); var usedMemoryPercentage = Math.Round(((_memoryInfo.UsedMemoryMB / (double)_memoryInfo.TotalMemoryMB) * 100.0), 2); @@ -515,7 +515,7 @@ public async Task RunCpuUtilizationMonitorAsync(string taskId) try { - await GetCpuInfoAsync(linkedTokenSource.Token, "Resource Utilization Warnings"); + await GetCpuInfoAsync(linkedTokenSource.Token); if (_cpuInfo.Usage >= CPU_UTILIZATION_PERCENTAGE_THRESHOLD) { diff --git a/src/Agent.Worker/RetryHelper.cs b/src/Agent.Worker/RetryHelper.cs index 2208eae0fc..28b584613d 100644 --- a/src/Agent.Worker/RetryHelper.cs +++ b/src/Agent.Worker/RetryHelper.cs @@ -81,9 +81,9 @@ public async Task RetryStep(Func action, Func timeDelayInterval) if (retryCounter > 0) { //ReInitialize _forceCompleted and _forceCompleteCancellationTokenSource - Trace.Info("##DEBUG_SB: Calling ReInitializeForceCompletedin RetryHelper.RetryStep"); + // Trace.Info("##DEBUG_SB: Calling ReInitializeForceCompletedin RetryHelper.RetryStep"); ExecutionContext.ReInitializeForceCompleted(); - Trace.Info("##DEBUG_SB: Called ReInitializeForceCompletedin RetryHelper.RetryStep"); + // Trace.Info("##DEBUG_SB: Called ReInitializeForceCompletedin RetryHelper.RetryStep"); } Debug($"Invoking Method: {action.Method}. Attempt count: {retryCounter}"); diff --git a/src/Agent.Worker/TaskCommandExtension.cs b/src/Agent.Worker/TaskCommandExtension.cs index 8ab45817a1..5f0a5bb8c6 100644 --- a/src/Agent.Worker/TaskCommandExtension.cs +++ b/src/Agent.Worker/TaskCommandExtension.cs @@ -529,7 +529,7 @@ public void Execute(IExecutionContext context, Command command) !String.IsNullOrEmpty(doneText) && StringUtil.ConvertToBoolean(doneText)) { - Trace.Info("##DEBUG_SB: Calling ForceTaskComplete from TaskCompleteCommand"); + // Trace.Info("##DEBUG_SB: Calling ForceTaskComplete from TaskCompleteCommand"); context.ForceTaskComplete(); } } From f832c54d7ede66f3a2e7bea1d9a9fcc193b344f6 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Fri, 13 Dec 2024 18:01:35 +0530 Subject: [PATCH 05/51] fixes --- src/Agent.Worker/ResourceMetricsManager.cs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index a22804c7da..60f09661f9 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -348,7 +348,7 @@ private async Task GetCpuInfoStringAsync(CancellationToken cancellationT { try { - await GetCpuInfoAsync(cancellationToken, source); + await GetCpuInfoAsync(cancellationToken); return StringUtil.Loc("ResourceMonitorCPUInfo", $"{_cpuInfo.Usage:0.00}"); } @@ -362,7 +362,7 @@ private string GetDiskInfoString() { try { - GetDiskInfo(source); + GetDiskInfo(); return StringUtil.Loc("ResourceMonitorDiskInfo", _diskInfo.VolumeRoot, @@ -379,7 +379,7 @@ private async Task GetMemoryInfoStringAsync(CancellationToken cancellati { try { - await GetMemoryInfoAsync(cancellationToken, source); + await GetMemoryInfoAsync(cancellationToken); return StringUtil.Loc("ResourceMonitorMemoryInfo", $"{_memoryInfo.UsedMemoryMB:0.00}", From d5dae1db44ce987ea5e28edd408348c2029fcb7d Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Mon, 23 Dec 2024 18:04:05 +0530 Subject: [PATCH 06/51] added tracing related to threads --- src/Agent.Sdk/ProcessInvoker.MacLinux.cs | 3 +++ src/Agent.Sdk/ProcessInvoker.cs | 26 ++++++++++++++++++++++ src/Agent.Worker/ResourceMetricsManager.cs | 7 ++++++ 3 files changed, 36 insertions(+) diff --git a/src/Agent.Sdk/ProcessInvoker.MacLinux.cs b/src/Agent.Sdk/ProcessInvoker.MacLinux.cs index 870751de30..658b90bcb7 100644 --- a/src/Agent.Sdk/ProcessInvoker.MacLinux.cs +++ b/src/Agent.Sdk/ProcessInvoker.MacLinux.cs @@ -47,9 +47,12 @@ private void NixKillProcessTree() { try { + Trace.Info("##DEBUG_SB: In try block of NixKillProcessTree"); if (_proc?.HasExited == false) { + Trace.Info($"##DEBUG_SB: before proc.Kill() in NixKillProcessTree, proc id is {_proc?.Id}"); _proc?.Kill(); + Trace.Info($"##DEBUG_SB: after proc.Kill() in NixKillProcessTree, proc is {_proc?.Id}"); } } catch (InvalidOperationException ex) diff --git a/src/Agent.Sdk/ProcessInvoker.cs b/src/Agent.Sdk/ProcessInvoker.cs index 81886657e5..4d33e1ca88 100644 --- a/src/Agent.Sdk/ProcessInvoker.cs +++ b/src/Agent.Sdk/ProcessInvoker.cs @@ -253,13 +253,17 @@ public async Task ExecuteAsync( // Ensure we process STDERR even the process exit event happen before we start read STDERR stream. if (_proc.StartInfo.RedirectStandardError) { + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Before incrementing _asyncStreamReaderCount for STDERR: {_asyncStreamReaderCount}"); Interlocked.Increment(ref _asyncStreamReaderCount); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] After incrementing _asyncStreamReaderCount for STDERR: {_asyncStreamReaderCount}"); } // Ensure we process STDOUT even the process exit event happen before we start read STDOUT stream. if (_proc.StartInfo.RedirectStandardOutput) { + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Before incrementing _asyncStreamReaderCount for STDOUT: {_asyncStreamReaderCount}"); Interlocked.Increment(ref _asyncStreamReaderCount); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] After incrementing _asyncStreamReaderCount for STDOUT: {_asyncStreamReaderCount}"); } // If StandardErrorEncoding or StandardOutputEncoding is not specified the on the @@ -346,24 +350,33 @@ public async Task ExecuteAsync( { Task outputSignal = _outputProcessEvent.WaitAsync(); Task[] tasks; + Trace.Info("##DEBUG_SB: whiletrueblock_processinvoker using block"); if (continueAfterCancelProcessTreeKillAttempt) { + Trace.Info("##DEBUG_SB: PInvokerA"); tasks = new Task[] { outputSignal, _processExitedCompletionSource.Task, afterCancelKillProcessTreeAttemptSignal.WaitAsync() }; + Trace.Info("##DEBUG_SB: PInvokerB"); } else { + Trace.Info("##DEBUG_SB: PInvokerC"); tasks = new Task[] { outputSignal, _processExitedCompletionSource.Task }; + Trace.Info("##DEBUG_SB: PInvokerD"); } + Trace.Info("##DEBUG_SB: before signaled await"); var signaled = await Task.WhenAny(tasks); + Trace.Info("##DEBUG_SB: after signaled await"); if (signaled == outputSignal) { + Trace.Info("##DEBUG_SB: ProcessOutput if signaled == outputSignal"); ProcessOutput(); } else { + Trace.Info("##DEBUG_SB: ProcessOutput if signaled != outputSignal"); _stopWatch.Stop(); break; } @@ -371,6 +384,7 @@ public async Task ExecuteAsync( // Just in case there was some pending output when the process shut down go ahead and check the // data buffers one last time before returning + Trace.Info("##DEBUG_SB: ProcessOutput before exit"); ProcessOutput(); if (_proc.HasExited) @@ -417,20 +431,25 @@ private void ProcessOutput() List errorData = new List(); List outputData = new List(); + Trace.Info("##DEBUG_SB: before errorLine dequeue."); string errorLine; while (_errorData.TryDequeue(out errorLine)) { errorData.Add(errorLine); } + Trace.Info("##DEBUG_SB: before outputLine dequeue."); string outputLine; while (_outputData.TryDequeue(out outputLine)) { outputData.Add(outputLine); } + Trace.Info($"##DEBUG_SB: Before reset thread info: Thread.CurrentThread.ManagedThreadId={Thread.CurrentThread.ManagedThreadId}"); _outputProcessEvent.Reset(); + Trace.Info($"##DEBUG_SB: After reset thread info: Thread.CurrentThread.ManagedThreadId={Thread.CurrentThread.ManagedThreadId}"); + Trace.Info("##DEBUG_SB: Writing the error lines"); // Write the error lines. if (errorData != null && this.ErrorDataReceived != null) { @@ -443,6 +462,7 @@ private void ProcessOutput() } } + Trace.Info("##DEBUG_SB: Writing the output lines"); // Process the output lines. if (outputData != null && this.OutputDataReceived != null) { @@ -459,6 +479,8 @@ private void ProcessOutput() internal protected virtual async Task CancelAndKillProcessTree(bool killProcessOnCancel) { + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Entering CancelAndKillProcessTree"); + bool gracefulShoutdown = TryUseGracefulShutdown && !killProcessOnCancel; ArgUtil.NotNull(_proc, nameof(_proc)); @@ -471,11 +493,13 @@ internal protected virtual async Task CancelAndKillProcessTree(bool killProcessO if (sigint_succeed) { Trace.Info("Process cancelled successfully through Ctrl+C/SIGINT."); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree"); return; } if (gracefulShoutdown) { + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree"); return; } @@ -483,12 +507,14 @@ internal protected virtual async Task CancelAndKillProcessTree(bool killProcessO if (sigterm_succeed) { Trace.Info("Process terminate successfully through Ctrl+Break/SIGTERM."); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree"); return; } } Trace.Info("Kill entire process tree since both cancel and terminate signal has been ignored by the target process."); KillProcessTree(); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree"); } private async Task SendSIGINT(TimeSpan timeout) diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index 60f09661f9..c094177dff 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -209,7 +209,9 @@ await processInvoker.ExecuteAsync( cancellationToken: cancellationToken); // Use second sample for more accurate calculation + Trace.Info($"##DEBUG_SB: All Outputs in CPU Info block: {outputs}"); var cpuInfoIdle = double.Parse(outputs[1].Split(' ', (char)StringSplitOptions.RemoveEmptyEntries)[6].Trim('%')); + Trace.Info($"##DEBUG_SB: CPU Info Idle: {cpuInfoIdle}"); lock (_cpuInfoLock) { @@ -321,6 +323,8 @@ await processInvoker.ExecuteAsync( killProcessOnCancel: true, cancellationToken: cancellationToken); + Trace.Info($"##DEBUG_SB: All Outputs in Memory Info block: {outputs}"); + var pageSize = int.Parse(outputs[0].Split(" ", StringSplitOptions.RemoveEmptyEntries)[7]); var pagesFree = long.Parse(outputs[1].Split(" ", StringSplitOptions.RemoveEmptyEntries)[2].Trim('.')); @@ -333,6 +337,9 @@ await processInvoker.ExecuteAsync( var freeMemory = (pagesFree + pagesInactive) * pageSize; var usedMemory = (pagesActive + pagesSpeculative + pagesWiredDown + pagesOccupied) * pageSize; + Trace.Info($"##DEBUG_SB: Free Memory: {freeMemory}"); + Trace.Info($"##DEBUG_SB: Used Memory: {usedMemory}"); + lock (_memoryInfoLock) { _memoryInfo.Updated = DateTime.Now; From 1435f394cc1e4b8f9a816a8bb90af684407d7988 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Thu, 26 Dec 2024 10:27:53 +0530 Subject: [PATCH 07/51] thread tracing --- src/Agent.Sdk/ProcessInvoker.cs | 5 +++++ src/Agent.Worker/ExecutionContext.cs | 3 ++- 2 files changed, 7 insertions(+), 1 deletion(-) diff --git a/src/Agent.Sdk/ProcessInvoker.cs b/src/Agent.Sdk/ProcessInvoker.cs index 4d33e1ca88..9c802ef0fd 100644 --- a/src/Agent.Sdk/ProcessInvoker.cs +++ b/src/Agent.Sdk/ProcessInvoker.cs @@ -562,6 +562,7 @@ private void StartReadStream(StreamReader reader, ConcurrentQueue dataBu { Task.Run(() => { + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Start reading stream."); while (!reader.EndOfStream) { string line = reader.ReadLine(); @@ -569,17 +570,21 @@ private void StartReadStream(StreamReader reader, ConcurrentQueue dataBu { if (DisableWorkerCommands) { + Trace.Info("##DEBUG_SB: Deactivating VSO commands."); line = StringUtil.DeactivateVsoCommands(line); } dataBuffer.Enqueue(line); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Enqueued line: {line}"); _outputProcessEvent.Set(); } } + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] STDOUT/STDERR stream read finished."); Trace.Info("STDOUT/STDERR stream read finished."); if (Interlocked.Decrement(ref _asyncStreamReaderCount) == 0 && _waitingOnStreams) { + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] All stream readers finished. Setting process exited completion source."); _processExitedCompletionSource.TrySetResult(true); } }); diff --git a/src/Agent.Worker/ExecutionContext.cs b/src/Agent.Worker/ExecutionContext.cs index 9c75f561f5..366bf882fa 100644 --- a/src/Agent.Worker/ExecutionContext.cs +++ b/src/Agent.Worker/ExecutionContext.cs @@ -765,10 +765,11 @@ public long Write(string tag, string inputMessage, bool canMaskSecrets = true) { lock (parentContext._loggerLock) { + Trace.Info($"##DEBUG_SB: Write to parent context log file: {message}"); parentContext._logger.Write(message); } } - + Trace.Info($"##DEBUG_SB: Execution Context - message write - Write to job level log file: {message}"); _jobServerQueue.QueueWebConsoleLine(_record.Id, message, totalLines); } From 96cd7572be83cb2800dd73b197f435d22d64eeb7 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Thu, 26 Dec 2024 15:08:12 +0530 Subject: [PATCH 08/51] test change in resourcemanager exec context --- src/Agent.Worker/TaskRunner.cs | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/src/Agent.Worker/TaskRunner.cs b/src/Agent.Worker/TaskRunner.cs index 4cfee6d9b2..73e5427934 100644 --- a/src/Agent.Worker/TaskRunner.cs +++ b/src/Agent.Worker/TaskRunner.cs @@ -415,7 +415,10 @@ private async Task RunAsyncInternal() IResourceMetricsManager resourceDiagnosticManager = null; resourceDiagnosticManager = HostContext.GetService(); - resourceDiagnosticManager.SetContext(ExecutionContext); + // resourceDiagnosticManager.SetContext(ExecutionContext); + + resourceDiagnosticManager.SetContext(ExecutionContext.CreateChild(Guid.NewGuid(), nameof(ResourceMetricsManager), $"{nameof(ResourceMetricsManager)}_Run")); + Trace.Info("##DEBUG_SB: ResourceDiagnosticManager is initialized with child context."); if (enableResourceUtilizationWarnings) { From a6d789ded79cfd585d1631a060bb44cbe9b8ca22 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Fri, 27 Dec 2024 13:54:16 +0530 Subject: [PATCH 09/51] publish telemetry disabled check --- src/Agent.Sdk/ProcessInvoker.cs | 1 + src/Agent.Worker/ResourceMetricsManager.cs | 4 +++- src/Agent.Worker/TaskRunner.cs | 6 +++--- 3 files changed, 7 insertions(+), 4 deletions(-) diff --git a/src/Agent.Sdk/ProcessInvoker.cs b/src/Agent.Sdk/ProcessInvoker.cs index 9c802ef0fd..23ca185f8d 100644 --- a/src/Agent.Sdk/ProcessInvoker.cs +++ b/src/Agent.Sdk/ProcessInvoker.cs @@ -562,6 +562,7 @@ private void StartReadStream(StreamReader reader, ConcurrentQueue dataBu { Task.Run(() => { + //add _proc.id info everywhere that thread id is being logged Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Start reading stream."); while (!reader.EndOfStream) { diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index c094177dff..5aff0de9d8 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -528,7 +528,9 @@ public async Task RunCpuUtilizationMonitorAsync(string taskId) { string message = $"CPU utilization is higher than {CPU_UTILIZATION_PERCENTAGE_THRESHOLD}%; currently used: {_cpuInfo.Usage:0.00}%"; - PublishTelemetry(message, taskId); + Trace.Info($"##DEBUG_SB: CPU Utilization instead of publishTelemetry - {message}"); + //commented out PublishTelemetry for now + // PublishTelemetry(message, taskId); break; } diff --git a/src/Agent.Worker/TaskRunner.cs b/src/Agent.Worker/TaskRunner.cs index 73e5427934..fd19d996be 100644 --- a/src/Agent.Worker/TaskRunner.cs +++ b/src/Agent.Worker/TaskRunner.cs @@ -415,10 +415,10 @@ private async Task RunAsyncInternal() IResourceMetricsManager resourceDiagnosticManager = null; resourceDiagnosticManager = HostContext.GetService(); - // resourceDiagnosticManager.SetContext(ExecutionContext); + resourceDiagnosticManager.SetContext(ExecutionContext); - resourceDiagnosticManager.SetContext(ExecutionContext.CreateChild(Guid.NewGuid(), nameof(ResourceMetricsManager), $"{nameof(ResourceMetricsManager)}_Run")); - Trace.Info("##DEBUG_SB: ResourceDiagnosticManager is initialized with child context."); + // resourceDiagnosticManager.SetContext(ExecutionContext.CreateChild(Guid.NewGuid(), nameof(ResourceMetricsManager), $"{nameof(ResourceMetricsManager)}_Run")); + // Trace.Info("##DEBUG_SB: ResourceDiagnosticManager is initialized with child context."); if (enableResourceUtilizationWarnings) { From 327284dc0c0fc216294d813f95b5d8ffb5a5965a Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Fri, 27 Dec 2024 16:05:28 +0530 Subject: [PATCH 10/51] streamreader access check --- src/Agent.Sdk/ProcessInvoker.cs | 12 +++++++++++- src/Agent.Worker/ResourceMetricsManager.cs | 4 ++-- 2 files changed, 13 insertions(+), 3 deletions(-) diff --git a/src/Agent.Sdk/ProcessInvoker.cs b/src/Agent.Sdk/ProcessInvoker.cs index 23ca185f8d..b3d02b54cc 100644 --- a/src/Agent.Sdk/ProcessInvoker.cs +++ b/src/Agent.Sdk/ProcessInvoker.cs @@ -537,10 +537,20 @@ private async Task SendSIGTERM(TimeSpan timeout) return await SendPosixSignal(PosixSignals.SIGTERM, timeout); } + private readonly object _exithandlerlock = new object(); private void ProcessExitedHandler(object sender, EventArgs e) { Trace.Info($"Exited process {_proc.Id} with exit code {_proc.ExitCode}"); - if ((_proc.StartInfo.RedirectStandardError || _proc.StartInfo.RedirectStandardOutput) && _asyncStreamReaderCount != 0) + + // int asyncStreamReaderCount = Interlocked.CompareExchange(ref _asyncStreamReaderCount, 0, 0); + int asyncStreamReaderCount; + lock (_exithandlerlock) + { + asyncStreamReaderCount = _asyncStreamReaderCount; + } + Trace.Info($"##DEBUG_SB: Setting asyncStreamReaderCount to {asyncStreamReaderCount} using lock"); + + if ((_proc.StartInfo.RedirectStandardError || _proc.StartInfo.RedirectStandardOutput) && asyncStreamReaderCount != 0) { _waitingOnStreams = true; diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index 5aff0de9d8..ca032e7fce 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -528,9 +528,9 @@ public async Task RunCpuUtilizationMonitorAsync(string taskId) { string message = $"CPU utilization is higher than {CPU_UTILIZATION_PERCENTAGE_THRESHOLD}%; currently used: {_cpuInfo.Usage:0.00}%"; - Trace.Info($"##DEBUG_SB: CPU Utilization instead of publishTelemetry - {message}"); + // Trace.Info($"##DEBUG_SB: CPU Utilization instead of publishTelemetry - {message}"); //commented out PublishTelemetry for now - // PublishTelemetry(message, taskId); + PublishTelemetry(message, taskId); break; } From da1fed448fa9407e092d385a32ecc5fb170cc862 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Fri, 27 Dec 2024 16:33:27 +0530 Subject: [PATCH 11/51] compare exchange --- src/Agent.Sdk/ProcessInvoker.cs | 10 +--------- 1 file changed, 1 insertion(+), 9 deletions(-) diff --git a/src/Agent.Sdk/ProcessInvoker.cs b/src/Agent.Sdk/ProcessInvoker.cs index b3d02b54cc..7884e4f71f 100644 --- a/src/Agent.Sdk/ProcessInvoker.cs +++ b/src/Agent.Sdk/ProcessInvoker.cs @@ -537,20 +537,12 @@ private async Task SendSIGTERM(TimeSpan timeout) return await SendPosixSignal(PosixSignals.SIGTERM, timeout); } - private readonly object _exithandlerlock = new object(); private void ProcessExitedHandler(object sender, EventArgs e) { Trace.Info($"Exited process {_proc.Id} with exit code {_proc.ExitCode}"); - // int asyncStreamReaderCount = Interlocked.CompareExchange(ref _asyncStreamReaderCount, 0, 0); - int asyncStreamReaderCount; - lock (_exithandlerlock) - { - asyncStreamReaderCount = _asyncStreamReaderCount; - } - Trace.Info($"##DEBUG_SB: Setting asyncStreamReaderCount to {asyncStreamReaderCount} using lock"); - if ((_proc.StartInfo.RedirectStandardError || _proc.StartInfo.RedirectStandardOutput) && asyncStreamReaderCount != 0) + if ((_proc.StartInfo.RedirectStandardError || _proc.StartInfo.RedirectStandardOutput) && Interlocked.CompareExchange(ref _asyncStreamReaderCount, 0, 0) != 0) { _waitingOnStreams = true; From 74a3716db31546aef52e4ac14b903137b3373af1 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Mon, 30 Dec 2024 08:23:53 +0530 Subject: [PATCH 12/51] turning off memory and disk info monitor --- src/Agent.Sdk/ProcessInvoker.cs | 2 +- src/Agent.Worker/ResourceMetricsManager.cs | 2 +- src/Agent.Worker/TaskRunner.cs | 4 ++-- 3 files changed, 4 insertions(+), 4 deletions(-) diff --git a/src/Agent.Sdk/ProcessInvoker.cs b/src/Agent.Sdk/ProcessInvoker.cs index 7884e4f71f..fb4420b66e 100644 --- a/src/Agent.Sdk/ProcessInvoker.cs +++ b/src/Agent.Sdk/ProcessInvoker.cs @@ -542,7 +542,7 @@ private void ProcessExitedHandler(object sender, EventArgs e) Trace.Info($"Exited process {_proc.Id} with exit code {_proc.ExitCode}"); - if ((_proc.StartInfo.RedirectStandardError || _proc.StartInfo.RedirectStandardOutput) && Interlocked.CompareExchange(ref _asyncStreamReaderCount, 0, 0) != 0) + if ((_proc.StartInfo.RedirectStandardError || _proc.StartInfo.RedirectStandardOutput) && _asyncStreamReaderCount != 0) { _waitingOnStreams = true; diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index ca032e7fce..8b79a8678f 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -207,7 +207,7 @@ await processInvoker.ExecuteAsync( outputEncoding: null, killProcessOnCancel: true, cancellationToken: cancellationToken); - + //try setting killProcessOnCancel to false // Use second sample for more accurate calculation Trace.Info($"##DEBUG_SB: All Outputs in CPU Info block: {outputs}"); var cpuInfoIdle = double.Parse(outputs[1].Split(' ', (char)StringSplitOptions.RemoveEmptyEntries)[6].Trim('%')); diff --git a/src/Agent.Worker/TaskRunner.cs b/src/Agent.Worker/TaskRunner.cs index fd19d996be..82c321fae5 100644 --- a/src/Agent.Worker/TaskRunner.cs +++ b/src/Agent.Worker/TaskRunner.cs @@ -424,8 +424,8 @@ private async Task RunAsyncInternal() { // add tracing statement to indicate that resource utilization warnings are enabled Trace.Info("##DEBUG_SB: Resource utilization warnings are enabled."); - _ = resourceDiagnosticManager.RunMemoryUtilizationMonitorAsync(); - _ = resourceDiagnosticManager.RunDiskSpaceUtilizationMonitorAsync(); + // _ = resourceDiagnosticManager.RunMemoryUtilizationMonitorAsync(); + // _ = resourceDiagnosticManager.RunDiskSpaceUtilizationMonitorAsync(); _ = resourceDiagnosticManager.RunCpuUtilizationMonitorAsync(Task.Reference.Id.ToString()); } else From 73432db04de6cadf191ea37ff220c6f09f1a80c3 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Mon, 30 Dec 2024 09:26:53 +0530 Subject: [PATCH 13/51] monitors - cpu off, memory on --- src/Agent.Worker/TaskRunner.cs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/Agent.Worker/TaskRunner.cs b/src/Agent.Worker/TaskRunner.cs index 82c321fae5..c1aa13c104 100644 --- a/src/Agent.Worker/TaskRunner.cs +++ b/src/Agent.Worker/TaskRunner.cs @@ -424,9 +424,9 @@ private async Task RunAsyncInternal() { // add tracing statement to indicate that resource utilization warnings are enabled Trace.Info("##DEBUG_SB: Resource utilization warnings are enabled."); - // _ = resourceDiagnosticManager.RunMemoryUtilizationMonitorAsync(); + _ = resourceDiagnosticManager.RunMemoryUtilizationMonitorAsync(); // _ = resourceDiagnosticManager.RunDiskSpaceUtilizationMonitorAsync(); - _ = resourceDiagnosticManager.RunCpuUtilizationMonitorAsync(Task.Reference.Id.ToString()); + // _ = resourceDiagnosticManager.RunCpuUtilizationMonitorAsync(Task.Reference.Id.ToString()); } else { From 324a4031c18a4e14966af1e3679a2ab682eae10b Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Mon, 30 Dec 2024 09:48:01 +0530 Subject: [PATCH 14/51] cpu and memory info both enabled --- src/Agent.Worker/TaskRunner.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Agent.Worker/TaskRunner.cs b/src/Agent.Worker/TaskRunner.cs index c1aa13c104..3f9fdd2a59 100644 --- a/src/Agent.Worker/TaskRunner.cs +++ b/src/Agent.Worker/TaskRunner.cs @@ -426,7 +426,7 @@ private async Task RunAsyncInternal() Trace.Info("##DEBUG_SB: Resource utilization warnings are enabled."); _ = resourceDiagnosticManager.RunMemoryUtilizationMonitorAsync(); // _ = resourceDiagnosticManager.RunDiskSpaceUtilizationMonitorAsync(); - // _ = resourceDiagnosticManager.RunCpuUtilizationMonitorAsync(Task.Reference.Id.ToString()); + _ = resourceDiagnosticManager.RunCpuUtilizationMonitorAsync(Task.Reference.Id.ToString()); } else { From 5f95d4ab093858408abc6e13ae70b0db7b462016 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Mon, 30 Dec 2024 10:59:36 +0530 Subject: [PATCH 15/51] cancellationtoken update --- src/Agent.Worker/ResourceMetricsManager.cs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index 8b79a8678f..314ed9109d 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -419,7 +419,7 @@ await GetMemoryInfoStringAsync(linkedTokenSource.Token), await GetCpuInfoStringAsync(linkedTokenSource.Token))); Trace.Info($"##DEBUG_SB: Waiting for {ACTIVE_MODE_INTERVAL} ms"); - await Task.Delay(ACTIVE_MODE_INTERVAL, _context.CancellationToken); + await Task.Delay(ACTIVE_MODE_INTERVAL, linkedTokenSource.Token); Trace.Info($"##DEBUG_SB: Done waiting for {ACTIVE_MODE_INTERVAL} ms"); } Trace.Info("##DEBUG_SB: Exiting debug resource monitor"); @@ -499,7 +499,7 @@ public async Task RunMemoryUtilizationMonitorAsync() } Trace.Info($"##DEBUG_SB: Memory Utilization - Waiting for {WARNING_MESSAGE_INTERVAL} ms"); - await Task.Delay(WARNING_MESSAGE_INTERVAL, _context.CancellationToken); + await Task.Delay(WARNING_MESSAGE_INTERVAL, linkedTokenSource.Token); Trace.Info($"##DEBUG_SB: Memory Utilization - Done waiting for {WARNING_MESSAGE_INTERVAL} ms"); } @@ -544,7 +544,7 @@ public async Task RunCpuUtilizationMonitorAsync(string taskId) } Trace.Info($"##DEBUG_SB: CPU Utilization - Waiting for {WARNING_MESSAGE_INTERVAL} ms"); - await Task.Delay(WARNING_MESSAGE_INTERVAL, _context.CancellationToken); + await Task.Delay(WARNING_MESSAGE_INTERVAL, linkedTokenSource.Token); Trace.Info($"##DEBUG_SB: CPU Utilization - Done waiting for {WARNING_MESSAGE_INTERVAL} ms"); } Trace.Info("##DEBUG_SB: Exiting CPU utilization monitor"); From b1ac11ddb8fb6fa2055ff7b22cea07e64cc95110 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Mon, 30 Dec 2024 14:12:46 +0530 Subject: [PATCH 16/51] loop iteration trace --- src/Agent.Worker/ResourceMetricsManager.cs | 18 +++++++++++------- 1 file changed, 11 insertions(+), 7 deletions(-) diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index 314ed9109d..a7162953f1 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -419,7 +419,7 @@ await GetMemoryInfoStringAsync(linkedTokenSource.Token), await GetCpuInfoStringAsync(linkedTokenSource.Token))); Trace.Info($"##DEBUG_SB: Waiting for {ACTIVE_MODE_INTERVAL} ms"); - await Task.Delay(ACTIVE_MODE_INTERVAL, linkedTokenSource.Token); + await Task.Delay(ACTIVE_MODE_INTERVAL, _context.CancellationToken); Trace.Info($"##DEBUG_SB: Done waiting for {ACTIVE_MODE_INTERVAL} ms"); } Trace.Info("##DEBUG_SB: Exiting debug resource monitor"); @@ -464,8 +464,10 @@ public async Task RunDiskSpaceUtilizationMonitorAsync() public async Task RunMemoryUtilizationMonitorAsync() { Trace.Info("##DEBUG_SB: Starting memory utilization monitor"); + int iterationCount = 0; while (!_context.CancellationToken.IsCancellationRequested) { + iterationCount++; using var timeoutTokenSource = new CancellationTokenSource(); timeoutTokenSource.CancelAfter(TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)); @@ -498,9 +500,9 @@ public async Task RunMemoryUtilizationMonitorAsync() break; } - Trace.Info($"##DEBUG_SB: Memory Utilization - Waiting for {WARNING_MESSAGE_INTERVAL} ms"); - await Task.Delay(WARNING_MESSAGE_INTERVAL, linkedTokenSource.Token); - Trace.Info($"##DEBUG_SB: Memory Utilization - Done waiting for {WARNING_MESSAGE_INTERVAL} ms"); + Trace.Info($"##DEBUG_SB: Memory Utilization - Waiting for {WARNING_MESSAGE_INTERVAL} ms, iteration count: {iterationCount}"); + await Task.Delay(WARNING_MESSAGE_INTERVAL, _context.CancellationToken); + Trace.Info($"##DEBUG_SB: Memory Utilization - Done waiting for {WARNING_MESSAGE_INTERVAL} ms, iteration count: {iterationCount}"); } Trace.Info("##DEBUG_SB: Exiting memory utilization monitor"); @@ -509,8 +511,10 @@ public async Task RunMemoryUtilizationMonitorAsync() public async Task RunCpuUtilizationMonitorAsync(string taskId) { Trace.Info("##DEBUG_SB: Starting CPU utilization monitor"); + int iterationCount = 0; while (!_context.CancellationToken.IsCancellationRequested) { + iterationCount++; using var timeoutTokenSource = new CancellationTokenSource(); timeoutTokenSource.CancelAfter(TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)); @@ -543,9 +547,9 @@ public async Task RunCpuUtilizationMonitorAsync(string taskId) break; } - Trace.Info($"##DEBUG_SB: CPU Utilization - Waiting for {WARNING_MESSAGE_INTERVAL} ms"); - await Task.Delay(WARNING_MESSAGE_INTERVAL, linkedTokenSource.Token); - Trace.Info($"##DEBUG_SB: CPU Utilization - Done waiting for {WARNING_MESSAGE_INTERVAL} ms"); + Trace.Info($"##DEBUG_SB: CPU Utilization - Waiting for {WARNING_MESSAGE_INTERVAL} ms, iteration count: {iterationCount}"); + await Task.Delay(WARNING_MESSAGE_INTERVAL, _context.CancellationToken); + Trace.Info($"##DEBUG_SB: CPU Utilization - Done waiting for {WARNING_MESSAGE_INTERVAL} ms, iteration count: {iterationCount}"); } Trace.Info("##DEBUG_SB: Exiting CPU utilization monitor"); } From 694f83e08846d5ecc809128c38f0339adcc039b4 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Mon, 30 Dec 2024 14:43:56 +0530 Subject: [PATCH 17/51] added taskid --- src/Agent.Worker/ResourceMetricsManager.cs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index a7162953f1..6e899b7a2c 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -547,9 +547,9 @@ public async Task RunCpuUtilizationMonitorAsync(string taskId) break; } - Trace.Info($"##DEBUG_SB: CPU Utilization - Waiting for {WARNING_MESSAGE_INTERVAL} ms, iteration count: {iterationCount}"); + Trace.Info($"##DEBUG_SB: CPU Utilization - Waiting for {WARNING_MESSAGE_INTERVAL} ms, taskid: {taskId}, iteration count: {iterationCount}"); await Task.Delay(WARNING_MESSAGE_INTERVAL, _context.CancellationToken); - Trace.Info($"##DEBUG_SB: CPU Utilization - Done waiting for {WARNING_MESSAGE_INTERVAL} ms, iteration count: {iterationCount}"); + Trace.Info($"##DEBUG_SB: CPU Utilization - Done waiting for {WARNING_MESSAGE_INTERVAL} ms, taskid: {taskId}, iteration count: {iterationCount}"); } Trace.Info("##DEBUG_SB: Exiting CPU utilization monitor"); } From 121acaea81138f51fddbf82afdcdd9b5c9b8b2ff Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Mon, 30 Dec 2024 15:40:17 +0530 Subject: [PATCH 18/51] resource monitor locks --- src/Agent.Worker/ResourceMetricsManager.cs | 27 +++++++++++++++++----- 1 file changed, 21 insertions(+), 6 deletions(-) diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index 6e899b7a2c..024c9e94a1 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -42,9 +42,15 @@ public sealed class ResourceMetricsManager : AgentService, IResourceMetricsManag private static DiskInfo _diskInfo; private static MemoryInfo _memoryInfo; + + private static readonly object _cpuInfoLastUpdatedLock = new object(); + private static readonly object _diskInfoLastUpdatedLock = new object(); + private static readonly object _memoryInfoLastUpdatedLock = new object(); + private static readonly object _cpuInfoLock = new object(); private static readonly object _diskInfoLock = new object(); private static readonly object _memoryInfoLock = new object(); + #endregion #region MetricStructs @@ -113,9 +119,12 @@ private void PublishTelemetry(string message, string taskId) #region MetricMethods private async Task GetCpuInfoAsync(CancellationToken cancellationToken) { - if (_cpuInfo.Updated >= DateTime.Now - TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)) + lock (_cpuInfoLastUpdatedLock) { - return; + if (_cpuInfo.Updated >= DateTime.Now - TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)) + { + return; + } } if (PlatformUtil.RunningOnWindows) @@ -224,9 +233,12 @@ await processInvoker.ExecuteAsync( private void GetDiskInfo() { Trace.Info($"##DEBUG_SB: Getting disk info from source: "); - if (_diskInfo.Updated >= DateTime.Now - TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)) + lock (_diskInfoLastUpdatedLock) { - return; + if (_diskInfo.Updated >= DateTime.Now - TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)) + { + return; + } } string root = Path.GetPathRoot(_context.GetVariableValueOrDefault(Constants.Variables.Agent.WorkFolder)); @@ -243,9 +255,12 @@ private void GetDiskInfo() private async Task GetMemoryInfoAsync(CancellationToken cancellationToken) { - if (_memoryInfo.Updated >= DateTime.Now - TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)) + lock (_memoryInfoLastUpdatedLock) { - return; + if (_memoryInfo.Updated >= DateTime.Now - TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)) + { + return; + } } if (PlatformUtil.RunningOnWindows) From 6c742d120311e72d12bdc58362f5e63ee22e1150 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Mon, 30 Dec 2024 15:49:47 +0530 Subject: [PATCH 19/51] interlocked compare exchange --- src/Agent.Sdk/ProcessInvoker.cs | 2 +- src/Agent.Worker/TaskRunner.cs | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/src/Agent.Sdk/ProcessInvoker.cs b/src/Agent.Sdk/ProcessInvoker.cs index fb4420b66e..f69b23cf61 100644 --- a/src/Agent.Sdk/ProcessInvoker.cs +++ b/src/Agent.Sdk/ProcessInvoker.cs @@ -542,7 +542,7 @@ private void ProcessExitedHandler(object sender, EventArgs e) Trace.Info($"Exited process {_proc.Id} with exit code {_proc.ExitCode}"); - if ((_proc.StartInfo.RedirectStandardError || _proc.StartInfo.RedirectStandardOutput) && _asyncStreamReaderCount != 0) + if ((_proc.StartInfo.RedirectStandardError || _proc.StartInfo.RedirectStandardOutput) && Interlocked.CompareExchange(ref _asyncStreamReaderCount, 0, 0) > 0) { _waitingOnStreams = true; diff --git a/src/Agent.Worker/TaskRunner.cs b/src/Agent.Worker/TaskRunner.cs index 3f9fdd2a59..fd19d996be 100644 --- a/src/Agent.Worker/TaskRunner.cs +++ b/src/Agent.Worker/TaskRunner.cs @@ -425,7 +425,7 @@ private async Task RunAsyncInternal() // add tracing statement to indicate that resource utilization warnings are enabled Trace.Info("##DEBUG_SB: Resource utilization warnings are enabled."); _ = resourceDiagnosticManager.RunMemoryUtilizationMonitorAsync(); - // _ = resourceDiagnosticManager.RunDiskSpaceUtilizationMonitorAsync(); + _ = resourceDiagnosticManager.RunDiskSpaceUtilizationMonitorAsync(); _ = resourceDiagnosticManager.RunCpuUtilizationMonitorAsync(Task.Reference.Id.ToString()); } else From 7fb519fec71ba8c990465c54baff2574d99c7eba Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Mon, 30 Dec 2024 16:10:07 +0530 Subject: [PATCH 20/51] resource monitor lock and private task call --- src/Agent.Worker/ResourceMetricsManager.cs | 27 ++++++++++++++++++++++ src/Agent.Worker/TaskRunner.cs | 7 +++--- 2 files changed, 31 insertions(+), 3 deletions(-) diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index 024c9e94a1..1fb170f7c8 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -24,6 +24,7 @@ public interface IResourceMetricsManager : IAgentService Task RunDiskSpaceUtilizationMonitorAsync(); Task RunCpuUtilizationMonitorAsync(string taskId); void SetContext(IExecutionContext context); + void StartMonitors(string taskId); } public sealed class ResourceMetricsManager : AgentService, IResourceMetricsManager @@ -51,6 +52,11 @@ public sealed class ResourceMetricsManager : AgentService, IResourceMetricsManag private static readonly object _diskInfoLock = new object(); private static readonly object _memoryInfoLock = new object(); + private Task _cpuMonitorTask; + private Task _memoryMonitorTask; + private Task _diskMonitorTask; + private readonly object _monitorLock = new object(); + #endregion #region MetricStructs @@ -568,6 +574,27 @@ public async Task RunCpuUtilizationMonitorAsync(string taskId) } Trace.Info("##DEBUG_SB: Exiting CPU utilization monitor"); } + + public void StartMonitors(string taskId) + { + lock (_monitorLock) + { + if (_cpuMonitorTask == null || _cpuMonitorTask.IsCompleted) + { + _cpuMonitorTask = RunCpuUtilizationMonitorAsync(taskId); + } + + if (_memoryMonitorTask == null || _memoryMonitorTask.IsCompleted) + { + _memoryMonitorTask = RunMemoryUtilizationMonitorAsync(); + } + + if (_diskMonitorTask == null || _diskMonitorTask.IsCompleted) + { + _diskMonitorTask = RunDiskSpaceUtilizationMonitorAsync(); + } + } + } #endregion } } diff --git a/src/Agent.Worker/TaskRunner.cs b/src/Agent.Worker/TaskRunner.cs index fd19d996be..914abf6a06 100644 --- a/src/Agent.Worker/TaskRunner.cs +++ b/src/Agent.Worker/TaskRunner.cs @@ -424,9 +424,10 @@ private async Task RunAsyncInternal() { // add tracing statement to indicate that resource utilization warnings are enabled Trace.Info("##DEBUG_SB: Resource utilization warnings are enabled."); - _ = resourceDiagnosticManager.RunMemoryUtilizationMonitorAsync(); - _ = resourceDiagnosticManager.RunDiskSpaceUtilizationMonitorAsync(); - _ = resourceDiagnosticManager.RunCpuUtilizationMonitorAsync(Task.Reference.Id.ToString()); + _ = resourceDiagnosticManager.StartMonitors(Task.Reference.Id.ToString()); + // _ = resourceDiagnosticManager.RunMemoryUtilizationMonitorAsync(); + // _ = resourceDiagnosticManager.RunDiskSpaceUtilizationMonitorAsync(); + // _ = resourceDiagnosticManager.RunCpuUtilizationMonitorAsync(Task.Reference.Id.ToString()); } else { From 8b0d7ba1b35bc1d21f5ca35275c7910b78c54907 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Mon, 30 Dec 2024 16:11:33 +0530 Subject: [PATCH 21/51] syntax fix --- src/Agent.Worker/TaskRunner.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Agent.Worker/TaskRunner.cs b/src/Agent.Worker/TaskRunner.cs index 914abf6a06..796c4fa946 100644 --- a/src/Agent.Worker/TaskRunner.cs +++ b/src/Agent.Worker/TaskRunner.cs @@ -424,7 +424,7 @@ private async Task RunAsyncInternal() { // add tracing statement to indicate that resource utilization warnings are enabled Trace.Info("##DEBUG_SB: Resource utilization warnings are enabled."); - _ = resourceDiagnosticManager.StartMonitors(Task.Reference.Id.ToString()); + resourceDiagnosticManager.StartMonitors(Task.Reference.Id.ToString()); // _ = resourceDiagnosticManager.RunMemoryUtilizationMonitorAsync(); // _ = resourceDiagnosticManager.RunDiskSpaceUtilizationMonitorAsync(); // _ = resourceDiagnosticManager.RunCpuUtilizationMonitorAsync(Task.Reference.Id.ToString()); From 57f8150d51e5aace296e0a2c0a44fe99d0af20a3 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Tue, 31 Dec 2024 12:05:05 +0530 Subject: [PATCH 22/51] job extension and workercommandmanager tracing --- src/Agent.Sdk/ProcessInvoker.cs | 4 +- src/Agent.Worker/ExecutionContext.cs | 3 + src/Agent.Worker/JobExtension.cs | 1 + src/Agent.Worker/ResourceMetricsManager.cs | 86 +++++++++++----------- src/Agent.Worker/TaskRunner.cs | 8 +- src/Agent.Worker/WorkerCommandManager.cs | 5 +- 6 files changed, 57 insertions(+), 50 deletions(-) diff --git a/src/Agent.Sdk/ProcessInvoker.cs b/src/Agent.Sdk/ProcessInvoker.cs index f69b23cf61..d8f7592d76 100644 --- a/src/Agent.Sdk/ProcessInvoker.cs +++ b/src/Agent.Sdk/ProcessInvoker.cs @@ -541,8 +541,8 @@ private void ProcessExitedHandler(object sender, EventArgs e) { Trace.Info($"Exited process {_proc.Id} with exit code {_proc.ExitCode}"); - - if ((_proc.StartInfo.RedirectStandardError || _proc.StartInfo.RedirectStandardOutput) && Interlocked.CompareExchange(ref _asyncStreamReaderCount, 0, 0) > 0) + // if ((_proc.StartInfo.RedirectStandardError || _proc.StartInfo.RedirectStandardOutput) && Interlocked.CompareExchange(ref _asyncStreamReaderCount, 0, 0) > 0) + if ((_proc.StartInfo.RedirectStandardError || _proc.StartInfo.RedirectStandardOutput) && _asyncStreamReaderCount != 0) { _waitingOnStreams = true; diff --git a/src/Agent.Worker/ExecutionContext.cs b/src/Agent.Worker/ExecutionContext.cs index 366bf882fa..a6c0e12dc8 100644 --- a/src/Agent.Worker/ExecutionContext.cs +++ b/src/Agent.Worker/ExecutionContext.cs @@ -339,7 +339,9 @@ public TaskResult Complete(TaskResult? result = null, string currentOperation = } _record.CurrentOperation = currentOperation ?? _record.CurrentOperation; + Trace.Info($"##DEBUG_SB: BEFORE Task result code: '{_record.ResultCode}'."); _record.ResultCode = resultCode ?? _record.ResultCode; + Trace.Info($"##DEBUG_SB: AFTER Task result code: '{_record.ResultCode}'."); _record.FinishTime = DateTime.UtcNow; _record.PercentComplete = 100; Trace.Info($"##DEBUG_SB: BEFORE Task result: '{_record.Result}'."); @@ -741,6 +743,7 @@ private string GetWorkspaceIdentifier(Pipelines.AgentJobRequestMessage message) public long Write(string tag, string inputMessage, bool canMaskSecrets = true) { string message = canMaskSecrets ? HostContext.SecretMasker.MaskSecrets($"{tag}{inputMessage}") : inputMessage; + Trace.Info($"##DEBUG_SB: Raw message: {message}"); long totalLines; lock (_loggerLock) diff --git a/src/Agent.Worker/JobExtension.cs b/src/Agent.Worker/JobExtension.cs index eae84a27be..173af76d2c 100644 --- a/src/Agent.Worker/JobExtension.cs +++ b/src/Agent.Worker/JobExtension.cs @@ -472,6 +472,7 @@ public async Task> InitializeJob(IExecutionContext jobContext, Pipel { if (await PlatformUtil.IsRunningOnAppleSiliconAsX64Async(timeout.Token)) { + Trace.Info("##DEBUG_SB: Rosetta2Warning Found. Running on Apple Silicon as x64."); jobContext.Warning(StringUtil.Loc("Rosetta2Warning")); } } diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index 1fb170f7c8..492776f999 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -24,7 +24,7 @@ public interface IResourceMetricsManager : IAgentService Task RunDiskSpaceUtilizationMonitorAsync(); Task RunCpuUtilizationMonitorAsync(string taskId); void SetContext(IExecutionContext context); - void StartMonitors(string taskId); + // void StartMonitors(string taskId); } public sealed class ResourceMetricsManager : AgentService, IResourceMetricsManager @@ -44,18 +44,18 @@ public sealed class ResourceMetricsManager : AgentService, IResourceMetricsManag private static MemoryInfo _memoryInfo; - private static readonly object _cpuInfoLastUpdatedLock = new object(); - private static readonly object _diskInfoLastUpdatedLock = new object(); - private static readonly object _memoryInfoLastUpdatedLock = new object(); + // private static readonly object _cpuInfoLastUpdatedLock = new object(); + // private static readonly object _diskInfoLastUpdatedLock = new object(); + // private static readonly object _memoryInfoLastUpdatedLock = new object(); private static readonly object _cpuInfoLock = new object(); private static readonly object _diskInfoLock = new object(); private static readonly object _memoryInfoLock = new object(); - private Task _cpuMonitorTask; - private Task _memoryMonitorTask; - private Task _diskMonitorTask; - private readonly object _monitorLock = new object(); + // private Task _cpuMonitorTask; + // private Task _memoryMonitorTask; + // private Task _diskMonitorTask; + // private readonly object _monitorLock = new object(); #endregion @@ -125,13 +125,13 @@ private void PublishTelemetry(string message, string taskId) #region MetricMethods private async Task GetCpuInfoAsync(CancellationToken cancellationToken) { - lock (_cpuInfoLastUpdatedLock) + // lock (_cpuInfoLastUpdatedLock) + // { + if (_cpuInfo.Updated >= DateTime.Now - TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)) { - if (_cpuInfo.Updated >= DateTime.Now - TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)) - { - return; - } + return; } + // } if (PlatformUtil.RunningOnWindows) { @@ -239,13 +239,13 @@ await processInvoker.ExecuteAsync( private void GetDiskInfo() { Trace.Info($"##DEBUG_SB: Getting disk info from source: "); - lock (_diskInfoLastUpdatedLock) + // lock (_diskInfoLastUpdatedLock) + // { + if (_diskInfo.Updated >= DateTime.Now - TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)) { - if (_diskInfo.Updated >= DateTime.Now - TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)) - { - return; - } + return; } + // } string root = Path.GetPathRoot(_context.GetVariableValueOrDefault(Constants.Variables.Agent.WorkFolder)); var driveInfo = new DriveInfo(root); @@ -261,13 +261,13 @@ private void GetDiskInfo() private async Task GetMemoryInfoAsync(CancellationToken cancellationToken) { - lock (_memoryInfoLastUpdatedLock) + // lock (_memoryInfoLastUpdatedLock) + // { + if (_memoryInfo.Updated >= DateTime.Now - TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)) { - if (_memoryInfo.Updated >= DateTime.Now - TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)) - { - return; - } + return; } + // } if (PlatformUtil.RunningOnWindows) { @@ -575,26 +575,26 @@ public async Task RunCpuUtilizationMonitorAsync(string taskId) Trace.Info("##DEBUG_SB: Exiting CPU utilization monitor"); } - public void StartMonitors(string taskId) - { - lock (_monitorLock) - { - if (_cpuMonitorTask == null || _cpuMonitorTask.IsCompleted) - { - _cpuMonitorTask = RunCpuUtilizationMonitorAsync(taskId); - } - - if (_memoryMonitorTask == null || _memoryMonitorTask.IsCompleted) - { - _memoryMonitorTask = RunMemoryUtilizationMonitorAsync(); - } - - if (_diskMonitorTask == null || _diskMonitorTask.IsCompleted) - { - _diskMonitorTask = RunDiskSpaceUtilizationMonitorAsync(); - } - } - } + // public void StartMonitors(string taskId) + // { + // lock (_monitorLock) + // { + // if (_cpuMonitorTask == null || _cpuMonitorTask.IsCompleted) + // { + // _cpuMonitorTask = RunCpuUtilizationMonitorAsync(taskId); + // } + + // if (_memoryMonitorTask == null || _memoryMonitorTask.IsCompleted) + // { + // _memoryMonitorTask = RunMemoryUtilizationMonitorAsync(); + // } + + // if (_diskMonitorTask == null || _diskMonitorTask.IsCompleted) + // { + // _diskMonitorTask = RunDiskSpaceUtilizationMonitorAsync(); + // } + // } + // } #endregion } } diff --git a/src/Agent.Worker/TaskRunner.cs b/src/Agent.Worker/TaskRunner.cs index 796c4fa946..1d277ab5ae 100644 --- a/src/Agent.Worker/TaskRunner.cs +++ b/src/Agent.Worker/TaskRunner.cs @@ -424,10 +424,10 @@ private async Task RunAsyncInternal() { // add tracing statement to indicate that resource utilization warnings are enabled Trace.Info("##DEBUG_SB: Resource utilization warnings are enabled."); - resourceDiagnosticManager.StartMonitors(Task.Reference.Id.ToString()); - // _ = resourceDiagnosticManager.RunMemoryUtilizationMonitorAsync(); - // _ = resourceDiagnosticManager.RunDiskSpaceUtilizationMonitorAsync(); - // _ = resourceDiagnosticManager.RunCpuUtilizationMonitorAsync(Task.Reference.Id.ToString()); + // resourceDiagnosticManager.StartMonitors(Task.Reference.Id.ToString()); + _ = resourceDiagnosticManager.RunMemoryUtilizationMonitorAsync(); + _ = resourceDiagnosticManager.RunDiskSpaceUtilizationMonitorAsync(); + _ = resourceDiagnosticManager.RunCpuUtilizationMonitorAsync(Task.Reference.Id.ToString()); } else { diff --git a/src/Agent.Worker/WorkerCommandManager.cs b/src/Agent.Worker/WorkerCommandManager.cs index eb310f155e..0df6cbdbb0 100644 --- a/src/Agent.Worker/WorkerCommandManager.cs +++ b/src/Agent.Worker/WorkerCommandManager.cs @@ -108,12 +108,13 @@ public bool TryProcessCommand(IExecutionContext context, string input) { try { + Trace.Info($"##DEBUG_SB: In try block of command serialize lock"); extension.ProcessCommand(context, command); } catch (SocketException ex) { using var vssConnection = WorkerUtilities.GetVssConnection(context); - + Trace.Info($"##DEBUG_SB: SocketException occurred in command serialize lock"); ExceptionsUtil.HandleSocketException(ex, vssConnection.Uri.ToString(), context.Error); context.CommandResult = TaskResult.Failed; } @@ -121,6 +122,7 @@ public bool TryProcessCommand(IExecutionContext context, string input) { context.Error(StringUtil.Loc("CommandProcessFailed", input)); context.Error(ex); + Trace.Info($"##DEBUG_SB: Exception occurred in command serialize lock"); context.CommandResult = TaskResult.Failed; } finally @@ -129,6 +131,7 @@ public bool TryProcessCommand(IExecutionContext context, string input) if (!(string.Equals(command.Area, "task", StringComparison.OrdinalIgnoreCase) && string.Equals(command.Event, "debug", StringComparison.OrdinalIgnoreCase))) { + Trace.Info($"##DEBUG_SB: In finally block of command serialize lock"); context.Debug($"Processed: {CommandStringConvertor.Unescape(input, unescapePercents)}"); } } From 7d4c8cd479bad95fb27165b3af734d0560f0e2aa Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Tue, 31 Dec 2024 14:21:25 +0530 Subject: [PATCH 23/51] cancellation token tracing --- src/Agent.Worker/ResourceMetricsManager.cs | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index 492776f999..758e506f63 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -476,6 +476,8 @@ public async Task RunDiskSpaceUtilizationMonitorAsync() } Trace.Info($"##DEBUG_SB: Disk Space Utilization - Waiting for {WARNING_MESSAGE_INTERVAL} ms"); + var isCancelled = _context.CancellationToken.IsCancellationRequested; + Trace.Info($"##DEBUG_SB: Disk Space Utilization - Is Cancellation Requested, Before Task.Delay: {isCancelled}"); await Task.Delay(WARNING_MESSAGE_INTERVAL, _context.CancellationToken); Trace.Info($"##DEBUG_SB: Disk Space Utilization - Done waiting for {WARNING_MESSAGE_INTERVAL} ms"); } @@ -522,6 +524,8 @@ public async Task RunMemoryUtilizationMonitorAsync() } Trace.Info($"##DEBUG_SB: Memory Utilization - Waiting for {WARNING_MESSAGE_INTERVAL} ms, iteration count: {iterationCount}"); + var isCancelled = _context.CancellationToken.IsCancellationRequested; + Trace.Info($"##DEBUG_SB: Memory Utilization - Is Cancellation Requested, Before Task.Delay: {isCancelled}"); await Task.Delay(WARNING_MESSAGE_INTERVAL, _context.CancellationToken); Trace.Info($"##DEBUG_SB: Memory Utilization - Done waiting for {WARNING_MESSAGE_INTERVAL} ms, iteration count: {iterationCount}"); } @@ -569,6 +573,9 @@ public async Task RunCpuUtilizationMonitorAsync(string taskId) } Trace.Info($"##DEBUG_SB: CPU Utilization - Waiting for {WARNING_MESSAGE_INTERVAL} ms, taskid: {taskId}, iteration count: {iterationCount}"); + //check if cancellation token has been cancelled + var isCancelled = _context.CancellationToken.IsCancellationRequested; + Trace.Info($"##DEBUG_SB: CPU Utilization - Is Cancellation Requested, Before Task.Delay: {isCancelled}"); await Task.Delay(WARNING_MESSAGE_INTERVAL, _context.CancellationToken); Trace.Info($"##DEBUG_SB: CPU Utilization - Done waiting for {WARNING_MESSAGE_INTERVAL} ms, taskid: {taskId}, iteration count: {iterationCount}"); } From 63ff3cd81972958d4197223f875231563fcc8d1e Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Tue, 31 Dec 2024 15:03:39 +0530 Subject: [PATCH 24/51] commented resourcediagnostics from steps runner, tracing for context.warning added --- src/Agent.Worker/ResourceMetricsManager.cs | 2 ++ src/Agent.Worker/StepsRunner.cs | 4 ++-- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index 758e506f63..3b891588c8 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -460,6 +460,7 @@ public async Task RunDiskSpaceUtilizationMonitorAsync() if (freeDiskSpacePercentage <= AVAILABLE_DISK_SPACE_PERCENTAGE_THRESHOLD) { + Trace.Info("##DEBUG_SB: ResourceMonitorFreeDiskSpaceIsLowerThanThreshold, context.Warning called"); _context.Warning(StringUtil.Loc("ResourceMonitorFreeDiskSpaceIsLowerThanThreshold", _diskInfo.VolumeRoot, AVAILABLE_DISK_SPACE_PERCENTAGE_THRESHOLD, @@ -509,6 +510,7 @@ public async Task RunMemoryUtilizationMonitorAsync() if (100.0 - usedMemoryPercentage <= AVAILABLE_MEMORY_PERCENTAGE_THRESHOLD) { + Trace.Info("##DEBUG_SB: ResourceMonitorMemorySpaceIsLowerThanThreshold, context.Warning called"); _context.Warning(StringUtil.Loc("ResourceMonitorMemorySpaceIsLowerThanThreshold", AVAILABLE_MEMORY_PERCENTAGE_THRESHOLD, $"{usedMemoryPercentage:0.00}")); diff --git a/src/Agent.Worker/StepsRunner.cs b/src/Agent.Worker/StepsRunner.cs index fec9264aaf..aca3c04208 100644 --- a/src/Agent.Worker/StepsRunner.cs +++ b/src/Agent.Worker/StepsRunner.cs @@ -88,8 +88,8 @@ public async Task RunAsync(IExecutionContext jobContext, IList steps) } // Change the current job context to the step context. - var resourceDiagnosticManager = HostContext.GetService(); - resourceDiagnosticManager.SetContext(step.ExecutionContext); + // var resourceDiagnosticManager = HostContext.GetService(); + // resourceDiagnosticManager.SetContext(step.ExecutionContext); // Variable expansion. step.ExecutionContext.SetStepTarget(step.Target); From 83506529a0fdb3566b3a926ee39a87adf7b2aac2 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Tue, 31 Dec 2024 15:32:02 +0530 Subject: [PATCH 25/51] commenting out resource debug monitor --- src/Agent.Worker/JobRunner.cs | 28 ++++++++++++++-------------- 1 file changed, 14 insertions(+), 14 deletions(-) diff --git a/src/Agent.Worker/JobRunner.cs b/src/Agent.Worker/JobRunner.cs index dfdd1ad8d2..a481b26919 100644 --- a/src/Agent.Worker/JobRunner.cs +++ b/src/Agent.Worker/JobRunner.cs @@ -114,20 +114,20 @@ public async Task RunAsync(Pipelines.AgentJobRequestMessage message, //Start Resource Diagnostics if enabled in the job message jobContext.Variables.TryGetValue("system.debug", out var systemDebug); - resourceDiagnosticManager = HostContext.GetService(); - resourceDiagnosticManager.SetContext(jobContext); - - if (string.Equals(systemDebug, "true", StringComparison.OrdinalIgnoreCase)) - { - if (AgentKnobs.EnableResourceMonitorDebugOutput.GetValue(jobContext).AsBoolean()) - { - _ = resourceDiagnosticManager.RunDebugResourceMonitorAsync(); - } - else - { - jobContext.Debug(StringUtil.Loc("ResourceUtilizationDebugOutputIsDisabled")); - } - } + // resourceDiagnosticManager = HostContext.GetService(); + // resourceDiagnosticManager.SetContext(jobContext); + + // if (string.Equals(systemDebug, "true", StringComparison.OrdinalIgnoreCase)) + // { + // if (AgentKnobs.EnableResourceMonitorDebugOutput.GetValue(jobContext).AsBoolean()) + // { + // _ = resourceDiagnosticManager.RunDebugResourceMonitorAsync(); + // } + // else + // { + // jobContext.Debug(StringUtil.Loc("ResourceUtilizationDebugOutputIsDisabled")); + // } + // } agentShutdownRegistration = HostContext.AgentShutdownToken.Register(() => { From 9f5b55c4f17069a2fab407bd282490e07beb87a6 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Tue, 31 Dec 2024 15:33:38 +0530 Subject: [PATCH 26/51] minor fix --- src/Agent.Worker/JobRunner.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Agent.Worker/JobRunner.cs b/src/Agent.Worker/JobRunner.cs index a481b26919..62c0b1a4ca 100644 --- a/src/Agent.Worker/JobRunner.cs +++ b/src/Agent.Worker/JobRunner.cs @@ -100,7 +100,7 @@ public async Task RunAsync(Pipelines.AgentJobRequestMessage message, CancellationTokenRegistration? agentShutdownRegistration = null; VssConnection taskConnection = null; VssConnection legacyTaskConnection = null; - IResourceMetricsManager resourceDiagnosticManager = null; + // IResourceMetricsManager resourceDiagnosticManager = null; try { // Create the job execution context. From db7be63eb4e402f47a150528f6e3b08377645205 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Tue, 31 Dec 2024 15:48:39 +0530 Subject: [PATCH 27/51] added process ids to tracings in invoker; added continueaftercancelprocesstreekillattempt arg --- src/Agent.Sdk/ProcessInvoker.cs | 58 +++++++++++----------- src/Agent.Worker/ResourceMetricsManager.cs | 6 ++- 2 files changed, 33 insertions(+), 31 deletions(-) diff --git a/src/Agent.Sdk/ProcessInvoker.cs b/src/Agent.Sdk/ProcessInvoker.cs index d8f7592d76..b04d8c6e58 100644 --- a/src/Agent.Sdk/ProcessInvoker.cs +++ b/src/Agent.Sdk/ProcessInvoker.cs @@ -336,12 +336,12 @@ public async Task ExecuteAsync( AsyncManualResetEvent afterCancelKillProcessTreeAttemptSignal = new AsyncManualResetEvent(); using (var registration = cancellationToken.Register(async () => { - Trace.Info("##DEBUG_SB: Cancellation requested, attempting to cancel and kill process tree."); + Trace.Info($"##DEBUG_SB: Cancellation requested, attempting to cancel and kill process tree for process {_proc.Id}."); await CancelAndKillProcessTree(killProcessOnCancel); // signal to ensure we exit the loop after we attempt to cancel and kill the process tree (which is best effort) afterCancelKillProcessTreeAttemptSignal.Set(); - Trace.Info("##DEBUG_SB: Cancellation requested, process tree killed."); + Trace.Info($"##DEBUG_SB: Cancellation requested, process tree killed for process {_proc.Id}."); })) { Trace.Info($"Process started with process id {_proc.Id}, waiting for process exit."); @@ -350,33 +350,33 @@ public async Task ExecuteAsync( { Task outputSignal = _outputProcessEvent.WaitAsync(); Task[] tasks; - Trace.Info("##DEBUG_SB: whiletrueblock_processinvoker using block"); + Trace.Info($"##DEBUG_SB: whiletrueblock_processinvoker using block for process {_proc.Id}."); if (continueAfterCancelProcessTreeKillAttempt) { - Trace.Info("##DEBUG_SB: PInvokerA"); + Trace.Info($"##DEBUG_SB: PInvokerA for process {_proc.Id}."); tasks = new Task[] { outputSignal, _processExitedCompletionSource.Task, afterCancelKillProcessTreeAttemptSignal.WaitAsync() }; - Trace.Info("##DEBUG_SB: PInvokerB"); + Trace.Info($"##DEBUG_SB: PInvokerB for process {_proc.Id}."); } else { - Trace.Info("##DEBUG_SB: PInvokerC"); + Trace.Info($"##DEBUG_SB: PInvokerC for process {_proc.Id}."); tasks = new Task[] { outputSignal, _processExitedCompletionSource.Task }; - Trace.Info("##DEBUG_SB: PInvokerD"); + Trace.Info($"##DEBUG_SB: PInvokerD for process {_proc.Id}."); } - Trace.Info("##DEBUG_SB: before signaled await"); + Trace.Info($"##DEBUG_SB: before signaled await for process {_proc.Id}."); var signaled = await Task.WhenAny(tasks); - Trace.Info("##DEBUG_SB: after signaled await"); + Trace.Info($"##DEBUG_SB: after signaled await for process {_proc.Id}."); if (signaled == outputSignal) { - Trace.Info("##DEBUG_SB: ProcessOutput if signaled == outputSignal"); + Trace.Info($"##DEBUG_SB: ProcessOutput if signaled == outputSignal for process {_proc.Id}."); ProcessOutput(); } else { - Trace.Info("##DEBUG_SB: ProcessOutput if signaled != outputSignal"); + Trace.Info($"##DEBUG_SB: ProcessOutput if signaled != outputSignal for process {_proc.Id}."); _stopWatch.Stop(); break; } @@ -384,7 +384,7 @@ public async Task ExecuteAsync( // Just in case there was some pending output when the process shut down go ahead and check the // data buffers one last time before returning - Trace.Info("##DEBUG_SB: ProcessOutput before exit"); + Trace.Info($"##DEBUG_SB: ProcessOutput before exit for process {_proc.Id}."); ProcessOutput(); if (_proc.HasExited) @@ -431,25 +431,25 @@ private void ProcessOutput() List errorData = new List(); List outputData = new List(); - Trace.Info("##DEBUG_SB: before errorLine dequeue."); + Trace.Info($"##DEBUG_SB: before errorLine dequeue for process {_proc.Id}."); string errorLine; while (_errorData.TryDequeue(out errorLine)) { errorData.Add(errorLine); } - Trace.Info("##DEBUG_SB: before outputLine dequeue."); + Trace.Info($"##DEBUG_SB: before outputLine dequeue for process {_proc.Id}."); string outputLine; while (_outputData.TryDequeue(out outputLine)) { outputData.Add(outputLine); } - Trace.Info($"##DEBUG_SB: Before reset thread info: Thread.CurrentThread.ManagedThreadId={Thread.CurrentThread.ManagedThreadId}"); + Trace.Info($"##DEBUG_SB: Before reset thread info: Thread.CurrentThread.ManagedThreadId={Thread.CurrentThread.ManagedThreadId} for process {_proc.Id}."); _outputProcessEvent.Reset(); - Trace.Info($"##DEBUG_SB: After reset thread info: Thread.CurrentThread.ManagedThreadId={Thread.CurrentThread.ManagedThreadId}"); + Trace.Info($"##DEBUG_SB: After reset thread info: Thread.CurrentThread.ManagedThreadId={Thread.CurrentThread.ManagedThreadId} for process {_proc.Id}."); - Trace.Info("##DEBUG_SB: Writing the error lines"); + Trace.Info($"##DEBUG_SB: Writing the error lines for process {_proc.Id}."); // Write the error lines. if (errorData != null && this.ErrorDataReceived != null) { @@ -462,7 +462,7 @@ private void ProcessOutput() } } - Trace.Info("##DEBUG_SB: Writing the output lines"); + Trace.Info($"##DEBUG_SB: Writing the output lines for process {_proc.Id}."); // Process the output lines. if (outputData != null && this.OutputDataReceived != null) { @@ -479,7 +479,7 @@ private void ProcessOutput() internal protected virtual async Task CancelAndKillProcessTree(bool killProcessOnCancel) { - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Entering CancelAndKillProcessTree"); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Entering CancelAndKillProcessTree for process {_proc.Id}."); bool gracefulShoutdown = TryUseGracefulShutdown && !killProcessOnCancel; @@ -493,13 +493,13 @@ internal protected virtual async Task CancelAndKillProcessTree(bool killProcessO if (sigint_succeed) { Trace.Info("Process cancelled successfully through Ctrl+C/SIGINT."); - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree"); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree for process {_proc.Id}."); return; } if (gracefulShoutdown) { - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree"); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree for process {_proc.Id}."); return; } @@ -507,14 +507,14 @@ internal protected virtual async Task CancelAndKillProcessTree(bool killProcessO if (sigterm_succeed) { Trace.Info("Process terminate successfully through Ctrl+Break/SIGTERM."); - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree"); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree for process {_proc.Id}."); return; } } Trace.Info("Kill entire process tree since both cancel and terminate signal has been ignored by the target process."); KillProcessTree(); - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree"); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree for process {_proc.Id}."); } private async Task SendSIGINT(TimeSpan timeout) @@ -565,7 +565,7 @@ private void StartReadStream(StreamReader reader, ConcurrentQueue dataBu Task.Run(() => { //add _proc.id info everywhere that thread id is being logged - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Start reading stream."); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Start reading stream for process {_proc.Id}."); while (!reader.EndOfStream) { string line = reader.ReadLine(); @@ -573,21 +573,21 @@ private void StartReadStream(StreamReader reader, ConcurrentQueue dataBu { if (DisableWorkerCommands) { - Trace.Info("##DEBUG_SB: Deactivating VSO commands."); + Trace.Info($"##DEBUG_SB: Deactivating VSO commands for process {_proc.Id}."); line = StringUtil.DeactivateVsoCommands(line); } dataBuffer.Enqueue(line); - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Enqueued line: {line}"); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Enqueued line: {line} for process {_proc.Id}."); _outputProcessEvent.Set(); } } - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] STDOUT/STDERR stream read finished."); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] STDOUT/STDERR stream read finished for process {_proc.Id}."); Trace.Info("STDOUT/STDERR stream read finished."); if (Interlocked.Decrement(ref _asyncStreamReaderCount) == 0 && _waitingOnStreams) { - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] All stream readers finished. Setting process exited completion source."); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] All stream readers finished. Setting process exited completion source for process {_proc.Id}."); _processExitedCompletionSource.TrySetResult(true); } }); @@ -614,7 +614,7 @@ private void StartWriteStream(InputQueue redirectStandardIn, StreamWrite if (!keepStandardInOpen) { - Trace.Info("Close STDIN after the first redirect finished."); + Trace.Info($"Close STDIN after the first redirect finished. for process {_proc.Id}."); standardIn.Close(); break; } diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index 3b891588c8..7b349b896d 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -221,7 +221,8 @@ await processInvoker.ExecuteAsync( requireExitCodeZero: true, outputEncoding: null, killProcessOnCancel: true, - cancellationToken: cancellationToken); + cancellationToken: cancellationToken, + continueAfterCancelProcessTreeKillAttempt: true); //try setting killProcessOnCancel to false // Use second sample for more accurate calculation Trace.Info($"##DEBUG_SB: All Outputs in CPU Info block: {outputs}"); @@ -342,7 +343,8 @@ await processInvoker.ExecuteAsync( requireExitCodeZero: true, outputEncoding: null, killProcessOnCancel: true, - cancellationToken: cancellationToken); + cancellationToken: cancellationToken, + continueAfterCancelProcessTreeKillAttempt: true); Trace.Info($"##DEBUG_SB: All Outputs in Memory Info block: {outputs}"); From 4ae188676088bff0d5d7941daa1e208f80e5ddcd Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Tue, 31 Dec 2024 15:57:07 +0530 Subject: [PATCH 28/51] execute async overload --- src/Agent.Worker/ResourceMetricsManager.cs | 16 ++++++++++++---- 1 file changed, 12 insertions(+), 4 deletions(-) diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index 7b349b896d..a842355c17 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -221,8 +221,12 @@ await processInvoker.ExecuteAsync( requireExitCodeZero: true, outputEncoding: null, killProcessOnCancel: true, - cancellationToken: cancellationToken, - continueAfterCancelProcessTreeKillAttempt: true); + redirectStandardIn: null, + inheritConsoleHandler: false, + keepStandardInOpen: false, + highPriorityProcess: false, + continueAfterCancelProcessTreeKillAttempt: true, + cancellationToken: cancellationToken); //try setting killProcessOnCancel to false // Use second sample for more accurate calculation Trace.Info($"##DEBUG_SB: All Outputs in CPU Info block: {outputs}"); @@ -343,8 +347,12 @@ await processInvoker.ExecuteAsync( requireExitCodeZero: true, outputEncoding: null, killProcessOnCancel: true, - cancellationToken: cancellationToken, - continueAfterCancelProcessTreeKillAttempt: true); + redirectStandardIn: null, + inheritConsoleHandler: false, + keepStandardInOpen: false, + highPriorityProcess: false, + continueAfterCancelProcessTreeKillAttempt: true, + cancellationToken: cancellationToken); Trace.Info($"##DEBUG_SB: All Outputs in Memory Info block: {outputs}"); From a2af9e1990d179b9d2401950a9cc98fc249435e9 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Tue, 31 Dec 2024 16:04:45 +0530 Subject: [PATCH 29/51] continue after cancel process tree false --- src/Agent.Worker/ResourceMetricsManager.cs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index a842355c17..280c8a71e4 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -225,7 +225,7 @@ await processInvoker.ExecuteAsync( inheritConsoleHandler: false, keepStandardInOpen: false, highPriorityProcess: false, - continueAfterCancelProcessTreeKillAttempt: true, + continueAfterCancelProcessTreeKillAttempt: false, cancellationToken: cancellationToken); //try setting killProcessOnCancel to false // Use second sample for more accurate calculation @@ -351,7 +351,7 @@ await processInvoker.ExecuteAsync( inheritConsoleHandler: false, keepStandardInOpen: false, highPriorityProcess: false, - continueAfterCancelProcessTreeKillAttempt: true, + continueAfterCancelProcessTreeKillAttempt: false, cancellationToken: cancellationToken); Trace.Info($"##DEBUG_SB: All Outputs in Memory Info block: {outputs}"); From 4b2a8cc0217532b8b474f2c05f268b245ac1e4c0 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Tue, 31 Dec 2024 16:34:30 +0530 Subject: [PATCH 30/51] removed args --- src/Agent.Sdk/ProcessInvoker.cs | 8 ++++---- src/Agent.Worker/ResourceMetricsManager.cs | 10 ---------- 2 files changed, 4 insertions(+), 14 deletions(-) diff --git a/src/Agent.Sdk/ProcessInvoker.cs b/src/Agent.Sdk/ProcessInvoker.cs index b04d8c6e58..8e50a5e926 100644 --- a/src/Agent.Sdk/ProcessInvoker.cs +++ b/src/Agent.Sdk/ProcessInvoker.cs @@ -493,13 +493,13 @@ internal protected virtual async Task CancelAndKillProcessTree(bool killProcessO if (sigint_succeed) { Trace.Info("Process cancelled successfully through Ctrl+C/SIGINT."); - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree for process {_proc.Id}."); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree for process {_proc?.Id}."); return; } if (gracefulShoutdown) { - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree for process {_proc.Id}."); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree for process {_proc?.Id}."); return; } @@ -507,14 +507,14 @@ internal protected virtual async Task CancelAndKillProcessTree(bool killProcessO if (sigterm_succeed) { Trace.Info("Process terminate successfully through Ctrl+Break/SIGTERM."); - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree for process {_proc.Id}."); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree for process {_proc?.Id}."); return; } } Trace.Info("Kill entire process tree since both cancel and terminate signal has been ignored by the target process."); KillProcessTree(); - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree for process {_proc.Id}."); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree for process {_proc?.Id}."); } private async Task SendSIGINT(TimeSpan timeout) diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index 280c8a71e4..3b891588c8 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -221,11 +221,6 @@ await processInvoker.ExecuteAsync( requireExitCodeZero: true, outputEncoding: null, killProcessOnCancel: true, - redirectStandardIn: null, - inheritConsoleHandler: false, - keepStandardInOpen: false, - highPriorityProcess: false, - continueAfterCancelProcessTreeKillAttempt: false, cancellationToken: cancellationToken); //try setting killProcessOnCancel to false // Use second sample for more accurate calculation @@ -347,11 +342,6 @@ await processInvoker.ExecuteAsync( requireExitCodeZero: true, outputEncoding: null, killProcessOnCancel: true, - redirectStandardIn: null, - inheritConsoleHandler: false, - keepStandardInOpen: false, - highPriorityProcess: false, - continueAfterCancelProcessTreeKillAttempt: false, cancellationToken: cancellationToken); Trace.Info($"##DEBUG_SB: All Outputs in Memory Info block: {outputs}"); From aacf18546339bdf9074463cef789170bd62af149 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Thu, 2 Jan 2025 10:12:08 +0530 Subject: [PATCH 31/51] added process filename --- src/Agent.Sdk/ProcessInvoker.cs | 52 ++++++++++++++++----------------- 1 file changed, 26 insertions(+), 26 deletions(-) diff --git a/src/Agent.Sdk/ProcessInvoker.cs b/src/Agent.Sdk/ProcessInvoker.cs index 8e50a5e926..f11a48170d 100644 --- a/src/Agent.Sdk/ProcessInvoker.cs +++ b/src/Agent.Sdk/ProcessInvoker.cs @@ -336,12 +336,12 @@ public async Task ExecuteAsync( AsyncManualResetEvent afterCancelKillProcessTreeAttemptSignal = new AsyncManualResetEvent(); using (var registration = cancellationToken.Register(async () => { - Trace.Info($"##DEBUG_SB: Cancellation requested, attempting to cancel and kill process tree for process {_proc.Id}."); + Trace.Info($"##DEBUG_SB: Cancellation requested, attempting to cancel and kill process tree for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); await CancelAndKillProcessTree(killProcessOnCancel); // signal to ensure we exit the loop after we attempt to cancel and kill the process tree (which is best effort) afterCancelKillProcessTreeAttemptSignal.Set(); - Trace.Info($"##DEBUG_SB: Cancellation requested, process tree killed for process {_proc.Id}."); + Trace.Info($"##DEBUG_SB: Cancellation requested, process tree killed for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); })) { Trace.Info($"Process started with process id {_proc.Id}, waiting for process exit."); @@ -350,33 +350,33 @@ public async Task ExecuteAsync( { Task outputSignal = _outputProcessEvent.WaitAsync(); Task[] tasks; - Trace.Info($"##DEBUG_SB: whiletrueblock_processinvoker using block for process {_proc.Id}."); + Trace.Info($"##DEBUG_SB: whiletrueblock_processinvoker using block for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); if (continueAfterCancelProcessTreeKillAttempt) { - Trace.Info($"##DEBUG_SB: PInvokerA for process {_proc.Id}."); + Trace.Info($"##DEBUG_SB: PInvokerA for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); tasks = new Task[] { outputSignal, _processExitedCompletionSource.Task, afterCancelKillProcessTreeAttemptSignal.WaitAsync() }; - Trace.Info($"##DEBUG_SB: PInvokerB for process {_proc.Id}."); + Trace.Info($"##DEBUG_SB: PInvokerB for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); } else { - Trace.Info($"##DEBUG_SB: PInvokerC for process {_proc.Id}."); + Trace.Info($"##DEBUG_SB: PInvokerC for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); tasks = new Task[] { outputSignal, _processExitedCompletionSource.Task }; - Trace.Info($"##DEBUG_SB: PInvokerD for process {_proc.Id}."); + Trace.Info($"##DEBUG_SB: PInvokerD for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); } - Trace.Info($"##DEBUG_SB: before signaled await for process {_proc.Id}."); + Trace.Info($"##DEBUG_SB: before signaled await for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); var signaled = await Task.WhenAny(tasks); - Trace.Info($"##DEBUG_SB: after signaled await for process {_proc.Id}."); + Trace.Info($"##DEBUG_SB: after signaled await for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); if (signaled == outputSignal) { - Trace.Info($"##DEBUG_SB: ProcessOutput if signaled == outputSignal for process {_proc.Id}."); + Trace.Info($"##DEBUG_SB: ProcessOutput if signaled == outputSignal for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); ProcessOutput(); } else { - Trace.Info($"##DEBUG_SB: ProcessOutput if signaled != outputSignal for process {_proc.Id}."); + Trace.Info($"##DEBUG_SB: ProcessOutput if signaled != outputSignal for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); _stopWatch.Stop(); break; } @@ -384,7 +384,7 @@ public async Task ExecuteAsync( // Just in case there was some pending output when the process shut down go ahead and check the // data buffers one last time before returning - Trace.Info($"##DEBUG_SB: ProcessOutput before exit for process {_proc.Id}."); + Trace.Info($"##DEBUG_SB: ProcessOutput before exit for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); ProcessOutput(); if (_proc.HasExited) @@ -431,25 +431,25 @@ private void ProcessOutput() List errorData = new List(); List outputData = new List(); - Trace.Info($"##DEBUG_SB: before errorLine dequeue for process {_proc.Id}."); + Trace.Info($"##DEBUG_SB: before errorLine dequeue for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); string errorLine; while (_errorData.TryDequeue(out errorLine)) { errorData.Add(errorLine); } - Trace.Info($"##DEBUG_SB: before outputLine dequeue for process {_proc.Id}."); + Trace.Info($"##DEBUG_SB: before outputLine dequeue for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); string outputLine; while (_outputData.TryDequeue(out outputLine)) { outputData.Add(outputLine); } - Trace.Info($"##DEBUG_SB: Before reset thread info: Thread.CurrentThread.ManagedThreadId={Thread.CurrentThread.ManagedThreadId} for process {_proc.Id}."); + Trace.Info($"##DEBUG_SB: Before reset thread info: Thread.CurrentThread.ManagedThreadId={Thread.CurrentThread.ManagedThreadId} for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); _outputProcessEvent.Reset(); - Trace.Info($"##DEBUG_SB: After reset thread info: Thread.CurrentThread.ManagedThreadId={Thread.CurrentThread.ManagedThreadId} for process {_proc.Id}."); + Trace.Info($"##DEBUG_SB: After reset thread info: Thread.CurrentThread.ManagedThreadId={Thread.CurrentThread.ManagedThreadId} for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); - Trace.Info($"##DEBUG_SB: Writing the error lines for process {_proc.Id}."); + Trace.Info($"##DEBUG_SB: Writing the error lines for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); // Write the error lines. if (errorData != null && this.ErrorDataReceived != null) { @@ -462,7 +462,7 @@ private void ProcessOutput() } } - Trace.Info($"##DEBUG_SB: Writing the output lines for process {_proc.Id}."); + Trace.Info($"##DEBUG_SB: Writing the output lines for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); // Process the output lines. if (outputData != null && this.OutputDataReceived != null) { @@ -479,13 +479,13 @@ private void ProcessOutput() internal protected virtual async Task CancelAndKillProcessTree(bool killProcessOnCancel) { - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Entering CancelAndKillProcessTree for process {_proc.Id}."); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Entering CancelAndKillProcessTree for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); bool gracefulShoutdown = TryUseGracefulShutdown && !killProcessOnCancel; ArgUtil.NotNull(_proc, nameof(_proc)); - Trace.Info($"##DEBUG_SB: Cancel and kill process tree for process {_proc.Id}."); + Trace.Info($"##DEBUG_SB: Cancel and kill process tree for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); if (!killProcessOnCancel) { @@ -565,7 +565,7 @@ private void StartReadStream(StreamReader reader, ConcurrentQueue dataBu Task.Run(() => { //add _proc.id info everywhere that thread id is being logged - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Start reading stream for process {_proc.Id}."); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Start reading stream for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); while (!reader.EndOfStream) { string line = reader.ReadLine(); @@ -573,21 +573,21 @@ private void StartReadStream(StreamReader reader, ConcurrentQueue dataBu { if (DisableWorkerCommands) { - Trace.Info($"##DEBUG_SB: Deactivating VSO commands for process {_proc.Id}."); + Trace.Info($"##DEBUG_SB: Deactivating VSO commands for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); line = StringUtil.DeactivateVsoCommands(line); } dataBuffer.Enqueue(line); - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Enqueued line: {line} for process {_proc.Id}."); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Enqueued line: {line} for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); _outputProcessEvent.Set(); } } - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] STDOUT/STDERR stream read finished for process {_proc.Id}."); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] STDOUT/STDERR stream read finished for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); Trace.Info("STDOUT/STDERR stream read finished."); if (Interlocked.Decrement(ref _asyncStreamReaderCount) == 0 && _waitingOnStreams) { - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] All stream readers finished. Setting process exited completion source for process {_proc.Id}."); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] All stream readers finished. Setting process exited completion source for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); _processExitedCompletionSource.TrySetResult(true); } }); @@ -614,7 +614,7 @@ private void StartWriteStream(InputQueue redirectStandardIn, StreamWrite if (!keepStandardInOpen) { - Trace.Info($"Close STDIN after the first redirect finished. for process {_proc.Id}."); + Trace.Info($"Close STDIN after the first redirect finished. for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); standardIn.Close(); break; } From f0379685e805f1f0de81c6c507e2a42b4f5bc315 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Thu, 2 Jan 2025 12:19:14 +0530 Subject: [PATCH 32/51] added filename --- src/Agent.Sdk/ProcessInvoker.cs | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/Agent.Sdk/ProcessInvoker.cs b/src/Agent.Sdk/ProcessInvoker.cs index f11a48170d..fd364be00a 100644 --- a/src/Agent.Sdk/ProcessInvoker.cs +++ b/src/Agent.Sdk/ProcessInvoker.cs @@ -253,17 +253,17 @@ public async Task ExecuteAsync( // Ensure we process STDERR even the process exit event happen before we start read STDERR stream. if (_proc.StartInfo.RedirectStandardError) { - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Before incrementing _asyncStreamReaderCount for STDERR: {_asyncStreamReaderCount}"); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Before incrementing _asyncStreamReaderCount for STDERR: {_asyncStreamReaderCount} for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); Interlocked.Increment(ref _asyncStreamReaderCount); - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] After incrementing _asyncStreamReaderCount for STDERR: {_asyncStreamReaderCount}"); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] After incrementing _asyncStreamReaderCount for STDERR: {_asyncStreamReaderCount} for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); } // Ensure we process STDOUT even the process exit event happen before we start read STDOUT stream. if (_proc.StartInfo.RedirectStandardOutput) { - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Before incrementing _asyncStreamReaderCount for STDOUT: {_asyncStreamReaderCount}"); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Before incrementing _asyncStreamReaderCount for STDOUT: {_asyncStreamReaderCount} for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); Interlocked.Increment(ref _asyncStreamReaderCount); - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] After incrementing _asyncStreamReaderCount for STDOUT: {_asyncStreamReaderCount}"); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] After incrementing _asyncStreamReaderCount for STDOUT: {_asyncStreamReaderCount} for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); } // If StandardErrorEncoding or StandardOutputEncoding is not specified the on the From bf05f0f740565bbc6ae3d6839e173f9bf02071e8 Mon Sep 17 00:00:00 2001 From: Tarun Ramsinghani Date: Thu, 2 Jan 2025 14:47:03 +0530 Subject: [PATCH 33/51] Changes from tarun --- src/Agent.Sdk/ProcessInvoker.cs | 52 ++++++++------ src/Agent.Worker/ResourceMetricsManager.cs | 79 +++++++++++++--------- 2 files changed, 79 insertions(+), 52 deletions(-) diff --git a/src/Agent.Sdk/ProcessInvoker.cs b/src/Agent.Sdk/ProcessInvoker.cs index f11a48170d..d9dd3379f9 100644 --- a/src/Agent.Sdk/ProcessInvoker.cs +++ b/src/Agent.Sdk/ProcessInvoker.cs @@ -311,13 +311,13 @@ public async Task ExecuteAsync( // Start the standard error notifications, if appropriate. if (_proc.StartInfo.RedirectStandardError) { - StartReadStream(_proc.StandardError, _errorData); + StartReadStream(_proc.StandardError, _errorData, "STDERR1"); } // Start the standard output notifications, if appropriate. if (_proc.StartInfo.RedirectStandardOutput) { - StartReadStream(_proc.StandardOutput, _outputData); + StartReadStream(_proc.StandardOutput, _outputData, "STDOUTPUT1"); } if (_proc.StartInfo.RedirectStandardInput) @@ -420,6 +420,8 @@ protected virtual void Dispose(bool disposing) { if (_proc != null) { + //_proc.StandardInput.Dispose(); + //_proc.StandardError.Dispose(); _proc.Dispose(); _proc = null; } @@ -560,35 +562,43 @@ private void ProcessExitedHandler(object sender, EventArgs e) } } - private void StartReadStream(StreamReader reader, ConcurrentQueue dataBuffer) + private void StartReadStream(StreamReader reader, ConcurrentQueue dataBuffer, string bufferName) { Task.Run(() => { - //add _proc.id info everywhere that thread id is being logged - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Start reading stream for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); - while (!reader.EndOfStream) + try { - string line = reader.ReadLine(); - if (line != null) + //add _proc.id info everywhere that thread id is being logged + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Start reading stream for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); + while (!reader.EndOfStream) { - if (DisableWorkerCommands) + string line = reader.ReadLine(); + if (line != null) { - Trace.Info($"##DEBUG_SB: Deactivating VSO commands for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); - line = StringUtil.DeactivateVsoCommands(line); + if (DisableWorkerCommands) + { + Trace.Info($"##DEBUG_SB: Deactivating VSO commands for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); + line = StringUtil.DeactivateVsoCommands(line); + } + dataBuffer.Enqueue(line); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] {bufferName} Enqueued line: {line} for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); + _outputProcessEvent.Set(); } - dataBuffer.Enqueue(line); - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Enqueued line: {line} for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); - _outputProcessEvent.Set(); } - } - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] STDOUT/STDERR stream read finished for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); - Trace.Info("STDOUT/STDERR stream read finished."); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] STDOUT/STDERR {bufferName} stream read finished for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); - if (Interlocked.Decrement(ref _asyncStreamReaderCount) == 0 && _waitingOnStreams) - { - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] All stream readers finished. Setting process exited completion source for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); - _processExitedCompletionSource.TrySetResult(true); + if (Interlocked.Decrement(ref _asyncStreamReaderCount) == 0 && _waitingOnStreams) + { + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] All stream readers finished. Setting process exited completion source for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); + _processExitedCompletionSource.TrySetResult(true); + } + } + catch { + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] caught exception in {bufferName} for process {_proc.Id}"); + } + finally { + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting readstream {bufferName} for {_proc.Id}"); } }); } diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index 3b891588c8..dff4405437 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -62,6 +62,7 @@ public sealed class ResourceMetricsManager : AgentService, IResourceMetricsManag #region MetricStructs private struct CpuInfo { + public bool IsProcRunning; public DateTime Updated; public double Usage; } @@ -196,42 +197,58 @@ await Task.Run(() => } if (PlatformUtil.RunningOnMacOS) { - Trace.Info($"##DEBUG_SB: CPU info - Getting CPU usage on MacOS from source: "); - using var processInvoker = HostContext.CreateService(); - - List outputs = new List(); - processInvoker.OutputDataReceived += delegate (object sender, ProcessDataReceivedEventArgs message) + try { - outputs.Add(message.Data); - }; + if (_cpuInfo.IsProcRunning) return; - processInvoker.ErrorDataReceived += delegate (object sender, ProcessDataReceivedEventArgs message) - { - Trace.Error($"Error on receiving CPU info: {message.Data}"); - }; + Trace.Info($"##DEBUG_SB: CPU info - Getting CPU usage on MacOS from source: "); + using var processInvoker = HostContext.CreateService(); - var filePath = "/bin/bash"; - var arguments = "-c \"top -l 2 -o cpu | grep ^CPU\""; - Trace.Info($"##DEBUG_SB: CPU info - Executing {filePath} {arguments}; source: "); - await processInvoker.ExecuteAsync( - workingDirectory: string.Empty, - fileName: filePath, - arguments: arguments, - environment: null, - requireExitCodeZero: true, - outputEncoding: null, - killProcessOnCancel: true, - cancellationToken: cancellationToken); - //try setting killProcessOnCancel to false - // Use second sample for more accurate calculation - Trace.Info($"##DEBUG_SB: All Outputs in CPU Info block: {outputs}"); - var cpuInfoIdle = double.Parse(outputs[1].Split(' ', (char)StringSplitOptions.RemoveEmptyEntries)[6].Trim('%')); - Trace.Info($"##DEBUG_SB: CPU Info Idle: {cpuInfoIdle}"); + List outputs = new List(); + processInvoker.OutputDataReceived += delegate (object sender, ProcessDataReceivedEventArgs message) + { + outputs.Add(message.Data); + }; - lock (_cpuInfoLock) + processInvoker.ErrorDataReceived += delegate (object sender, ProcessDataReceivedEventArgs message) + { + Trace.Error($"Error on receiving CPU info: {message.Data}"); + }; + + var filePath = "/bin/bash"; + var arguments = "-c \"top -l 2 -o cpu | grep ^CPU\""; + Trace.Info($"##DEBUG_SB: CPU info - Executing {filePath} {arguments}; source: "); + lock (_cpuInfoLock) + { + _cpuInfo.IsProcRunning = true; + } + await processInvoker.ExecuteAsync( + workingDirectory: string.Empty, + fileName: filePath, + arguments: arguments, + environment: null, + requireExitCodeZero: true, + outputEncoding: null, + killProcessOnCancel: true, + cancellationToken: cancellationToken); + //try setting killProcessOnCancel to false + // Use second sample for more accurate calculation + Trace.Info($"##DEBUG_SB: All Outputs in CPU Info block: {outputs}"); + var cpuInfoIdle = double.Parse(outputs[1].Split(' ', (char)StringSplitOptions.RemoveEmptyEntries)[6].Trim('%')); + Trace.Info($"##DEBUG_SB: CPU Info Idle: {cpuInfoIdle}"); + + lock (_cpuInfoLock) + { + _cpuInfo.Updated = DateTime.Now; + _cpuInfo.Usage = 100 - cpuInfoIdle; + } + } + finally { - _cpuInfo.Updated = DateTime.Now; - _cpuInfo.Usage = 100 - cpuInfoIdle; + lock (_cpuInfoLock) + { + _cpuInfo.IsProcRunning= false; + } } } } From 5d157c9d431b6defb8e5dfcb8681eb57e3970138 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Thu, 2 Jan 2025 16:49:04 +0530 Subject: [PATCH 34/51] undo filename change inside redirect if-blocks --- src/Agent.Sdk/ProcessInvoker.cs | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/Agent.Sdk/ProcessInvoker.cs b/src/Agent.Sdk/ProcessInvoker.cs index a6699b6194..d9dd3379f9 100644 --- a/src/Agent.Sdk/ProcessInvoker.cs +++ b/src/Agent.Sdk/ProcessInvoker.cs @@ -253,17 +253,17 @@ public async Task ExecuteAsync( // Ensure we process STDERR even the process exit event happen before we start read STDERR stream. if (_proc.StartInfo.RedirectStandardError) { - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Before incrementing _asyncStreamReaderCount for STDERR: {_asyncStreamReaderCount} for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Before incrementing _asyncStreamReaderCount for STDERR: {_asyncStreamReaderCount}"); Interlocked.Increment(ref _asyncStreamReaderCount); - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] After incrementing _asyncStreamReaderCount for STDERR: {_asyncStreamReaderCount} for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] After incrementing _asyncStreamReaderCount for STDERR: {_asyncStreamReaderCount}"); } // Ensure we process STDOUT even the process exit event happen before we start read STDOUT stream. if (_proc.StartInfo.RedirectStandardOutput) { - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Before incrementing _asyncStreamReaderCount for STDOUT: {_asyncStreamReaderCount} for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Before incrementing _asyncStreamReaderCount for STDOUT: {_asyncStreamReaderCount}"); Interlocked.Increment(ref _asyncStreamReaderCount); - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] After incrementing _asyncStreamReaderCount for STDOUT: {_asyncStreamReaderCount} for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] After incrementing _asyncStreamReaderCount for STDOUT: {_asyncStreamReaderCount}"); } // If StandardErrorEncoding or StandardOutputEncoding is not specified the on the From f83784750c695c74fe8719021854a159ff68ded9 Mon Sep 17 00:00:00 2001 From: Tarun Ramsinghani Date: Thu, 2 Jan 2025 17:18:01 +0530 Subject: [PATCH 35/51] adding lock to not invoke th eprocess again and again --- src/Agent.Worker/ResourceMetricsManager.cs | 111 ++++++++++++--------- 1 file changed, 65 insertions(+), 46 deletions(-) diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index dff4405437..4ea20422c1 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -77,6 +77,7 @@ private struct DiskInfo public struct MemoryInfo { + public bool IsProcRunning; public DateTime Updated; public long TotalMemoryMB; public long UsedMemoryMB; @@ -197,9 +198,13 @@ await Task.Run(() => } if (PlatformUtil.RunningOnMacOS) { - try + lock (_cpuInfoLock) { if (_cpuInfo.IsProcRunning) return; + _cpuInfo.IsProcRunning = true; + } + try + { Trace.Info($"##DEBUG_SB: CPU info - Getting CPU usage on MacOS from source: "); using var processInvoker = HostContext.CreateService(); @@ -218,10 +223,7 @@ await Task.Run(() => var filePath = "/bin/bash"; var arguments = "-c \"top -l 2 -o cpu | grep ^CPU\""; Trace.Info($"##DEBUG_SB: CPU info - Executing {filePath} {arguments}; source: "); - lock (_cpuInfoLock) - { - _cpuInfo.IsProcRunning = true; - } + await processInvoker.ExecuteAsync( workingDirectory: string.Empty, fileName: filePath, @@ -330,59 +332,76 @@ await Task.Run(() => if (PlatformUtil.RunningOnMacOS) { - // vm_stat allows to get the most detailed information about memory usage on MacOS - // but unfortunately it returns values in pages and has no built-in arguments for custom output - // so we need to parse and cast the output manually + lock (_memoryInfoLock) + { + if (_memoryInfo.IsProcRunning) return; + _memoryInfo.IsProcRunning = true; + } + try + { - Trace.Info($"##DEBUG_SB: Getting memory info on MacOS from source: "); - using var processInvoker = HostContext.CreateService(); + // vm_stat allows to get the most detailed information about memory usage on MacOS + // but unfortunately it returns values in pages and has no built-in arguments for custom output + // so we need to parse and cast the output manually - List outputs = new List(); - processInvoker.OutputDataReceived += delegate (object sender, ProcessDataReceivedEventArgs message) - { - outputs.Add(message.Data); - }; + Trace.Info($"##DEBUG_SB: Getting memory info on MacOS from source: "); + using var processInvoker = HostContext.CreateService(); - processInvoker.ErrorDataReceived += delegate (object sender, ProcessDataReceivedEventArgs message) - { - Trace.Error($"Error on receiving memory info: {message.Data}"); - }; + List outputs = new List(); + processInvoker.OutputDataReceived += delegate (object sender, ProcessDataReceivedEventArgs message) + { + outputs.Add(message.Data); + }; - var filePath = "vm_stat"; - Trace.Info($"##DEBUG_SB: Memory info - Executing {filePath}; statement source: "); + processInvoker.ErrorDataReceived += delegate (object sender, ProcessDataReceivedEventArgs message) + { + Trace.Error($"Error on receiving memory info: {message.Data}"); + }; - await processInvoker.ExecuteAsync( - workingDirectory: string.Empty, - fileName: filePath, - arguments: string.Empty, - environment: null, - requireExitCodeZero: true, - outputEncoding: null, - killProcessOnCancel: true, - cancellationToken: cancellationToken); + var filePath = "vm_stat"; + Trace.Info($"##DEBUG_SB: Memory info - Executing {filePath}; statement source: "); - Trace.Info($"##DEBUG_SB: All Outputs in Memory Info block: {outputs}"); + await processInvoker.ExecuteAsync( + workingDirectory: string.Empty, + fileName: filePath, + arguments: string.Empty, + environment: null, + requireExitCodeZero: true, + outputEncoding: null, + killProcessOnCancel: true, + cancellationToken: cancellationToken); - var pageSize = int.Parse(outputs[0].Split(" ", StringSplitOptions.RemoveEmptyEntries)[7]); + Trace.Info($"##DEBUG_SB: All Outputs in Memory Info block: {outputs}"); - var pagesFree = long.Parse(outputs[1].Split(" ", StringSplitOptions.RemoveEmptyEntries)[2].Trim('.')); - var pagesActive = long.Parse(outputs[2].Split(" ", StringSplitOptions.RemoveEmptyEntries)[2].Trim('.')); - var pagesInactive = long.Parse(outputs[3].Split(" ", StringSplitOptions.RemoveEmptyEntries)[2].Trim('.')); - var pagesSpeculative = long.Parse(outputs[4].Split(" ", StringSplitOptions.RemoveEmptyEntries)[2].Trim('.')); - var pagesWiredDown = long.Parse(outputs[6].Split(" ", StringSplitOptions.RemoveEmptyEntries)[3].Trim('.')); - var pagesOccupied = long.Parse(outputs[16].Split(" ", StringSplitOptions.RemoveEmptyEntries)[4].Trim('.')); + var pageSize = int.Parse(outputs[0].Split(" ", StringSplitOptions.RemoveEmptyEntries)[7]); - var freeMemory = (pagesFree + pagesInactive) * pageSize; - var usedMemory = (pagesActive + pagesSpeculative + pagesWiredDown + pagesOccupied) * pageSize; + var pagesFree = long.Parse(outputs[1].Split(" ", StringSplitOptions.RemoveEmptyEntries)[2].Trim('.')); + var pagesActive = long.Parse(outputs[2].Split(" ", StringSplitOptions.RemoveEmptyEntries)[2].Trim('.')); + var pagesInactive = long.Parse(outputs[3].Split(" ", StringSplitOptions.RemoveEmptyEntries)[2].Trim('.')); + var pagesSpeculative = long.Parse(outputs[4].Split(" ", StringSplitOptions.RemoveEmptyEntries)[2].Trim('.')); + var pagesWiredDown = long.Parse(outputs[6].Split(" ", StringSplitOptions.RemoveEmptyEntries)[3].Trim('.')); + var pagesOccupied = long.Parse(outputs[16].Split(" ", StringSplitOptions.RemoveEmptyEntries)[4].Trim('.')); - Trace.Info($"##DEBUG_SB: Free Memory: {freeMemory}"); - Trace.Info($"##DEBUG_SB: Used Memory: {usedMemory}"); + var freeMemory = (pagesFree + pagesInactive) * pageSize; + var usedMemory = (pagesActive + pagesSpeculative + pagesWiredDown + pagesOccupied) * pageSize; - lock (_memoryInfoLock) + Trace.Info($"##DEBUG_SB: Free Memory: {freeMemory}"); + Trace.Info($"##DEBUG_SB: Used Memory: {usedMemory}"); + + lock (_memoryInfoLock) + { + _memoryInfo.Updated = DateTime.Now; + _memoryInfo.TotalMemoryMB = (freeMemory + usedMemory) / 1048576; + _memoryInfo.UsedMemoryMB = usedMemory / 1048576; + } + } + finally { - _memoryInfo.Updated = DateTime.Now; - _memoryInfo.TotalMemoryMB = (freeMemory + usedMemory) / 1048576; - _memoryInfo.UsedMemoryMB = usedMemory / 1048576; + lock (_memoryInfoLock) + { + + _memoryInfo.IsProcRunning = false; + } } } } From 3a0a74490b9418e238188090d06e63aaeafedf5f Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Fri, 3 Jan 2025 11:08:30 +0530 Subject: [PATCH 36/51] re-enable debug resource monitor in jobrunner --- src/Agent.Worker/JobRunner.cs | 30 +++++++++++++++--------------- 1 file changed, 15 insertions(+), 15 deletions(-) diff --git a/src/Agent.Worker/JobRunner.cs b/src/Agent.Worker/JobRunner.cs index 62c0b1a4ca..dfdd1ad8d2 100644 --- a/src/Agent.Worker/JobRunner.cs +++ b/src/Agent.Worker/JobRunner.cs @@ -100,7 +100,7 @@ public async Task RunAsync(Pipelines.AgentJobRequestMessage message, CancellationTokenRegistration? agentShutdownRegistration = null; VssConnection taskConnection = null; VssConnection legacyTaskConnection = null; - // IResourceMetricsManager resourceDiagnosticManager = null; + IResourceMetricsManager resourceDiagnosticManager = null; try { // Create the job execution context. @@ -114,20 +114,20 @@ public async Task RunAsync(Pipelines.AgentJobRequestMessage message, //Start Resource Diagnostics if enabled in the job message jobContext.Variables.TryGetValue("system.debug", out var systemDebug); - // resourceDiagnosticManager = HostContext.GetService(); - // resourceDiagnosticManager.SetContext(jobContext); - - // if (string.Equals(systemDebug, "true", StringComparison.OrdinalIgnoreCase)) - // { - // if (AgentKnobs.EnableResourceMonitorDebugOutput.GetValue(jobContext).AsBoolean()) - // { - // _ = resourceDiagnosticManager.RunDebugResourceMonitorAsync(); - // } - // else - // { - // jobContext.Debug(StringUtil.Loc("ResourceUtilizationDebugOutputIsDisabled")); - // } - // } + resourceDiagnosticManager = HostContext.GetService(); + resourceDiagnosticManager.SetContext(jobContext); + + if (string.Equals(systemDebug, "true", StringComparison.OrdinalIgnoreCase)) + { + if (AgentKnobs.EnableResourceMonitorDebugOutput.GetValue(jobContext).AsBoolean()) + { + _ = resourceDiagnosticManager.RunDebugResourceMonitorAsync(); + } + else + { + jobContext.Debug(StringUtil.Loc("ResourceUtilizationDebugOutputIsDisabled")); + } + } agentShutdownRegistration = HostContext.AgentShutdownToken.Register(() => { From d6c3f58ba2d742d11a334a22484376b63cde96c9 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Fri, 3 Jan 2025 11:28:16 +0530 Subject: [PATCH 37/51] remove try-catch-finally block --- src/Agent.Sdk/ProcessInvoker.cs | 52 ++++++++++++++++----------------- 1 file changed, 26 insertions(+), 26 deletions(-) diff --git a/src/Agent.Sdk/ProcessInvoker.cs b/src/Agent.Sdk/ProcessInvoker.cs index d9dd3379f9..32aaaf4b30 100644 --- a/src/Agent.Sdk/ProcessInvoker.cs +++ b/src/Agent.Sdk/ProcessInvoker.cs @@ -566,40 +566,40 @@ private void StartReadStream(StreamReader reader, ConcurrentQueue dataBu { Task.Run(() => { - try + // try + // { + //add _proc.id info everywhere that thread id is being logged + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Start reading stream for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); + while (!reader.EndOfStream) { - //add _proc.id info everywhere that thread id is being logged - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Start reading stream for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); - while (!reader.EndOfStream) + string line = reader.ReadLine(); + if (line != null) { - string line = reader.ReadLine(); - if (line != null) + if (DisableWorkerCommands) { - if (DisableWorkerCommands) - { - Trace.Info($"##DEBUG_SB: Deactivating VSO commands for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); - line = StringUtil.DeactivateVsoCommands(line); - } - dataBuffer.Enqueue(line); - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] {bufferName} Enqueued line: {line} for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); - _outputProcessEvent.Set(); + Trace.Info($"##DEBUG_SB: Deactivating VSO commands for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); + line = StringUtil.DeactivateVsoCommands(line); } + dataBuffer.Enqueue(line); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] {bufferName} Enqueued line: {line} for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); + _outputProcessEvent.Set(); } + } - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] STDOUT/STDERR {bufferName} stream read finished for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] STDOUT/STDERR {bufferName} stream read finished for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); - if (Interlocked.Decrement(ref _asyncStreamReaderCount) == 0 && _waitingOnStreams) - { - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] All stream readers finished. Setting process exited completion source for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); - _processExitedCompletionSource.TrySetResult(true); - } - } - catch { - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] caught exception in {bufferName} for process {_proc.Id}"); - } - finally { - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting readstream {bufferName} for {_proc.Id}"); + if (Interlocked.Decrement(ref _asyncStreamReaderCount) == 0 && _waitingOnStreams) + { + Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] All stream readers finished. Setting process exited completion source for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); + _processExitedCompletionSource.TrySetResult(true); } + // } + // catch { + // Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] caught exception in {bufferName} for process {_proc.Id}"); + // } + // finally { + // Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting readstream {bufferName} for {_proc.Id}"); + // } }); } From 4e35f5da4b6efdba693b36b6482cb0c3af256113 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Fri, 3 Jan 2025 12:41:22 +0530 Subject: [PATCH 38/51] disposing _proc stdinput and stderror --- src/Agent.Sdk/ProcessInvoker.cs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/Agent.Sdk/ProcessInvoker.cs b/src/Agent.Sdk/ProcessInvoker.cs index 32aaaf4b30..57f7176dce 100644 --- a/src/Agent.Sdk/ProcessInvoker.cs +++ b/src/Agent.Sdk/ProcessInvoker.cs @@ -420,8 +420,8 @@ protected virtual void Dispose(bool disposing) { if (_proc != null) { - //_proc.StandardInput.Dispose(); - //_proc.StandardError.Dispose(); + _proc.StandardInput.Dispose(); + _proc.StandardError.Dispose(); _proc.Dispose(); _proc = null; } From f217c6da047d34c56421533daf2934c37a9b3ee2 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Fri, 3 Jan 2025 14:58:32 +0530 Subject: [PATCH 39/51] proc stdout dispose --- src/Agent.Sdk/ProcessInvoker.cs | 1 + 1 file changed, 1 insertion(+) diff --git a/src/Agent.Sdk/ProcessInvoker.cs b/src/Agent.Sdk/ProcessInvoker.cs index 57f7176dce..333f63cca1 100644 --- a/src/Agent.Sdk/ProcessInvoker.cs +++ b/src/Agent.Sdk/ProcessInvoker.cs @@ -421,6 +421,7 @@ protected virtual void Dispose(bool disposing) if (_proc != null) { _proc.StandardInput.Dispose(); + _proc.StandardOutput.Dispose(); _proc.StandardError.Dispose(); _proc.Dispose(); _proc = null; From ea3e6f54fa7dfa61563a1344e973304da93993d4 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Mon, 6 Jan 2025 14:16:45 +0530 Subject: [PATCH 40/51] removing tracings - restoring few files to original state --- src/Agent.Worker/RetryHelper.cs | 2 -- src/Agent.Worker/TaskCommandExtension.cs | 1 - 2 files changed, 3 deletions(-) diff --git a/src/Agent.Worker/RetryHelper.cs b/src/Agent.Worker/RetryHelper.cs index 28b584613d..9e3aabe1b0 100644 --- a/src/Agent.Worker/RetryHelper.cs +++ b/src/Agent.Worker/RetryHelper.cs @@ -81,9 +81,7 @@ public async Task RetryStep(Func action, Func timeDelayInterval) if (retryCounter > 0) { //ReInitialize _forceCompleted and _forceCompleteCancellationTokenSource - // Trace.Info("##DEBUG_SB: Calling ReInitializeForceCompletedin RetryHelper.RetryStep"); ExecutionContext.ReInitializeForceCompleted(); - // Trace.Info("##DEBUG_SB: Called ReInitializeForceCompletedin RetryHelper.RetryStep"); } Debug($"Invoking Method: {action.Method}. Attempt count: {retryCounter}"); diff --git a/src/Agent.Worker/TaskCommandExtension.cs b/src/Agent.Worker/TaskCommandExtension.cs index 5f0a5bb8c6..38e949941a 100644 --- a/src/Agent.Worker/TaskCommandExtension.cs +++ b/src/Agent.Worker/TaskCommandExtension.cs @@ -529,7 +529,6 @@ public void Execute(IExecutionContext context, Command command) !String.IsNullOrEmpty(doneText) && StringUtil.ConvertToBoolean(doneText)) { - // Trace.Info("##DEBUG_SB: Calling ForceTaskComplete from TaskCompleteCommand"); context.ForceTaskComplete(); } } From 025af0f9bb8d7849d0fa543f2b41379a344e475d Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Mon, 6 Jan 2025 14:22:00 +0530 Subject: [PATCH 41/51] removing tracings - restoring few files to original state --- src/Agent.Sdk/ProcessInvoker.MacLinux.cs | 3 --- src/Agent.Worker/JobExtension.cs | 1 - src/Agent.Worker/TaskRunner.cs | 4 ---- src/Agent.Worker/WorkerCommandManager.cs | 5 +---- 4 files changed, 1 insertion(+), 12 deletions(-) diff --git a/src/Agent.Sdk/ProcessInvoker.MacLinux.cs b/src/Agent.Sdk/ProcessInvoker.MacLinux.cs index 658b90bcb7..870751de30 100644 --- a/src/Agent.Sdk/ProcessInvoker.MacLinux.cs +++ b/src/Agent.Sdk/ProcessInvoker.MacLinux.cs @@ -47,12 +47,9 @@ private void NixKillProcessTree() { try { - Trace.Info("##DEBUG_SB: In try block of NixKillProcessTree"); if (_proc?.HasExited == false) { - Trace.Info($"##DEBUG_SB: before proc.Kill() in NixKillProcessTree, proc id is {_proc?.Id}"); _proc?.Kill(); - Trace.Info($"##DEBUG_SB: after proc.Kill() in NixKillProcessTree, proc is {_proc?.Id}"); } } catch (InvalidOperationException ex) diff --git a/src/Agent.Worker/JobExtension.cs b/src/Agent.Worker/JobExtension.cs index 173af76d2c..eae84a27be 100644 --- a/src/Agent.Worker/JobExtension.cs +++ b/src/Agent.Worker/JobExtension.cs @@ -472,7 +472,6 @@ public async Task> InitializeJob(IExecutionContext jobContext, Pipel { if (await PlatformUtil.IsRunningOnAppleSiliconAsX64Async(timeout.Token)) { - Trace.Info("##DEBUG_SB: Rosetta2Warning Found. Running on Apple Silicon as x64."); jobContext.Warning(StringUtil.Loc("Rosetta2Warning")); } } diff --git a/src/Agent.Worker/TaskRunner.cs b/src/Agent.Worker/TaskRunner.cs index 1d277ab5ae..4cfee6d9b2 100644 --- a/src/Agent.Worker/TaskRunner.cs +++ b/src/Agent.Worker/TaskRunner.cs @@ -417,14 +417,10 @@ private async Task RunAsyncInternal() resourceDiagnosticManager = HostContext.GetService(); resourceDiagnosticManager.SetContext(ExecutionContext); - // resourceDiagnosticManager.SetContext(ExecutionContext.CreateChild(Guid.NewGuid(), nameof(ResourceMetricsManager), $"{nameof(ResourceMetricsManager)}_Run")); - // Trace.Info("##DEBUG_SB: ResourceDiagnosticManager is initialized with child context."); - if (enableResourceUtilizationWarnings) { // add tracing statement to indicate that resource utilization warnings are enabled Trace.Info("##DEBUG_SB: Resource utilization warnings are enabled."); - // resourceDiagnosticManager.StartMonitors(Task.Reference.Id.ToString()); _ = resourceDiagnosticManager.RunMemoryUtilizationMonitorAsync(); _ = resourceDiagnosticManager.RunDiskSpaceUtilizationMonitorAsync(); _ = resourceDiagnosticManager.RunCpuUtilizationMonitorAsync(Task.Reference.Id.ToString()); diff --git a/src/Agent.Worker/WorkerCommandManager.cs b/src/Agent.Worker/WorkerCommandManager.cs index 0df6cbdbb0..eb310f155e 100644 --- a/src/Agent.Worker/WorkerCommandManager.cs +++ b/src/Agent.Worker/WorkerCommandManager.cs @@ -108,13 +108,12 @@ public bool TryProcessCommand(IExecutionContext context, string input) { try { - Trace.Info($"##DEBUG_SB: In try block of command serialize lock"); extension.ProcessCommand(context, command); } catch (SocketException ex) { using var vssConnection = WorkerUtilities.GetVssConnection(context); - Trace.Info($"##DEBUG_SB: SocketException occurred in command serialize lock"); + ExceptionsUtil.HandleSocketException(ex, vssConnection.Uri.ToString(), context.Error); context.CommandResult = TaskResult.Failed; } @@ -122,7 +121,6 @@ public bool TryProcessCommand(IExecutionContext context, string input) { context.Error(StringUtil.Loc("CommandProcessFailed", input)); context.Error(ex); - Trace.Info($"##DEBUG_SB: Exception occurred in command serialize lock"); context.CommandResult = TaskResult.Failed; } finally @@ -131,7 +129,6 @@ public bool TryProcessCommand(IExecutionContext context, string input) if (!(string.Equals(command.Area, "task", StringComparison.OrdinalIgnoreCase) && string.Equals(command.Event, "debug", StringComparison.OrdinalIgnoreCase))) { - Trace.Info($"##DEBUG_SB: In finally block of command serialize lock"); context.Debug($"Processed: {CommandStringConvertor.Unescape(input, unescapePercents)}"); } } From 62eb8f0be64974174adf482959857ace6f048afe Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Mon, 6 Jan 2025 14:34:09 +0530 Subject: [PATCH 42/51] removing tracings - restoring few files to original state --- src/Agent.Worker/ExecutionContext.cs | 18 +------ src/Agent.Worker/Handlers/NodeHandler.cs | 6 --- src/Agent.Worker/StepsRunner.cs | 64 ------------------------ src/Agent.Worker/TaskRunner.cs | 2 - 4 files changed, 1 insertion(+), 89 deletions(-) diff --git a/src/Agent.Worker/ExecutionContext.cs b/src/Agent.Worker/ExecutionContext.cs index a6c0e12dc8..d38702e216 100644 --- a/src/Agent.Worker/ExecutionContext.cs +++ b/src/Agent.Worker/ExecutionContext.cs @@ -90,11 +90,6 @@ public interface IExecutionContext : IAgentService, IKnobValueContext void CancelForceTaskCompletion(); void EmitHostNode20FallbackTelemetry(bool node20ResultsInGlibCErrorHost); void PublishTaskRunnerTelemetry(Dictionary taskRunnerData); - - /// TO-DO: - /// Disposes the execution context. - /// - // void Dispose(); } public sealed class ExecutionContext : AgentService, IExecutionContext, IDisposable @@ -217,15 +212,11 @@ public void ForceTaskComplete() Trace.Info("Force finish current task in 5 sec."); Task.Run(async () => { - Trace.Info("##DEBUG_SB: Force finish task delay 5 sec."); await Task.Delay(TimeSpan.FromSeconds(5), ForceCompleteCancellationToken); if (!ForceCompleteCancellationToken.IsCancellationRequested) { - Trace.Info("##DEBUG_SB: if block trysetresult"); _forceCompleted?.TrySetResult(1); - Trace.Info("##DEBUG_SB: if block trysetresult done"); } - Trace.Info("##DEBUG_SB: Force finish task delay 5 sec. Done."); }); } @@ -339,14 +330,10 @@ public TaskResult Complete(TaskResult? result = null, string currentOperation = } _record.CurrentOperation = currentOperation ?? _record.CurrentOperation; - Trace.Info($"##DEBUG_SB: BEFORE Task result code: '{_record.ResultCode}'."); _record.ResultCode = resultCode ?? _record.ResultCode; - Trace.Info($"##DEBUG_SB: AFTER Task result code: '{_record.ResultCode}'."); _record.FinishTime = DateTime.UtcNow; _record.PercentComplete = 100; - Trace.Info($"##DEBUG_SB: BEFORE Task result: '{_record.Result}'."); _record.Result = _record.Result ?? TaskResult.Succeeded; - Trace.Info($"##DEBUG_SB: AFTER Task result: '{_record.Result}'."); _record.State = TimelineRecordState.Completed; _jobServerQueue.QueueTimelineRecordUpdate(_mainTimelineId, _record); @@ -743,7 +730,6 @@ private string GetWorkspaceIdentifier(Pipelines.AgentJobRequestMessage message) public long Write(string tag, string inputMessage, bool canMaskSecrets = true) { string message = canMaskSecrets ? HostContext.SecretMasker.MaskSecrets($"{tag}{inputMessage}") : inputMessage; - Trace.Info($"##DEBUG_SB: Raw message: {message}"); long totalLines; lock (_loggerLock) @@ -768,11 +754,10 @@ public long Write(string tag, string inputMessage, bool canMaskSecrets = true) { lock (parentContext._loggerLock) { - Trace.Info($"##DEBUG_SB: Write to parent context log file: {message}"); parentContext._logger.Write(message); } } - Trace.Info($"##DEBUG_SB: Execution Context - message write - Write to job level log file: {message}"); + _jobServerQueue.QueueWebConsoleLine(_record.Id, message, totalLines); } @@ -992,7 +977,6 @@ public void PublishTaskRunnerTelemetry(Dictionary taskRunnerData public void Dispose() { - Trace.Info("##DEBUG_SB: ExecutionContext.Dispose() was called"); _cancellationTokenSource?.Dispose(); _forceCompleteCancellationTokenSource?.Dispose(); diff --git a/src/Agent.Worker/Handlers/NodeHandler.cs b/src/Agent.Worker/Handlers/NodeHandler.cs index 0326c4c0da..b96712c559 100644 --- a/src/Agent.Worker/Handlers/NodeHandler.cs +++ b/src/Agent.Worker/Handlers/NodeHandler.cs @@ -256,27 +256,21 @@ public async Task RunAsync() cancellationToken: ExecutionContext.CancellationToken); // Wait for either the node exit or force finish through ##vso command - Trace.Info("##DEBUG_SB: Waiting for node process to exit."); await System.Threading.Tasks.Task.WhenAny(step, ExecutionContext.ForceCompleted); - Trace.Info("##DEBUG_SB: Node process has exited."); if (ExecutionContext.ForceCompleted.IsCompleted) { - Trace.Info("##DEBUG_SB: The task was marked as \"done\", but the process has not closed after 5 seconds. Treating the task as complete."); ExecutionContext.Debug("The task was marked as \"done\", but the process has not closed after 5 seconds. Treating the task as complete."); } else { - Trace.Info("##DEBUG_SB: force completed else block"); await step; - Trace.Info("##DEBUG_SB: force completed else block step has completed"); } } catch (ProcessExitCodeException ex) { if (enableResourceUtilizationWarnings && ex.ExitCode == 137) { - Trace.Error("##DEBUG_SB: The task was terminated because it consumed too much memory."); ExecutionContext.Error(StringUtil.Loc("AgentOutOfMemoryFailure")); } diff --git a/src/Agent.Worker/StepsRunner.cs b/src/Agent.Worker/StepsRunner.cs index aca3c04208..23b30cbc5d 100644 --- a/src/Agent.Worker/StepsRunner.cs +++ b/src/Agent.Worker/StepsRunner.cs @@ -213,10 +213,7 @@ public async Task RunAsync(IExecutionContext jobContext, IList steps) else { // Run the step. - Trace.Info("##DEBUG_SB: Running the step in StepsRunner."); await RunStepAsync(step, jobContext.CancellationToken); - Trace.Info($"##DEBUG_SB: Step result: {step.ExecutionContext.Result}"); - Trace.Info("##DEBUG_SB: Finished running the step in StepsRunner."); } } finally @@ -317,7 +314,6 @@ private async Task RunStepAsync(IStep step, CancellationToken jobCancellationTok step.ExecutionContext.Error(StringUtil.Loc("StepTimedOut")); // if the step already canceled, don't set it to failed. - Trace.Info($"##DEBUG_SB: check 1 step.ExecutionContext.CommandResult: {step.ExecutionContext.CommandResult}"); step.ExecutionContext.CommandResult = TaskResultUtil.MergeTaskResults(step.ExecutionContext.CommandResult, TaskResult.Failed); } else if (AgentKnobs.FailJobWhenAgentDies.GetValue(step.ExecutionContext).AsBoolean() && @@ -328,7 +324,6 @@ private async Task RunStepAsync(IStep step, CancellationToken jobCancellationTok step.ExecutionContext.Error(ex); // if the step already canceled, don't set it to failed. - Trace.Info($"##DEBUG_SB: check 2 step.ExecutionContext.CommandResult: {step.ExecutionContext.CommandResult}"); step.ExecutionContext.CommandResult = TaskResultUtil.MergeTaskResults(step.ExecutionContext.CommandResult, TaskResult.Failed); } else @@ -338,7 +333,6 @@ private async Task RunStepAsync(IStep step, CancellationToken jobCancellationTok step.ExecutionContext.Error(ex); // if the step already failed, don't set it to canceled. - Trace.Info($"##DEBUG_SB: check 3 step.ExecutionContext.CommandResult: {step.ExecutionContext.CommandResult}"); step.ExecutionContext.CommandResult = TaskResultUtil.MergeTaskResults(step.ExecutionContext.CommandResult, TaskResult.Canceled); } } @@ -349,7 +343,6 @@ private async Task RunStepAsync(IStep step, CancellationToken jobCancellationTok step.ExecutionContext.Error(ex); // if the step already canceled, don't set it to failed. - Trace.Info($"##DEBUG_SB: check 4 step.ExecutionContext.CommandResult: {step.ExecutionContext.CommandResult}"); step.ExecutionContext.CommandResult = TaskResultUtil.MergeTaskResults(step.ExecutionContext.CommandResult, TaskResult.Failed); } } @@ -357,8 +350,6 @@ private async Task RunStepAsync(IStep step, CancellationToken jobCancellationTok // Merge executioncontext result with command result if (step.ExecutionContext.CommandResult != null) { - Trace.Info($"##DEBUG_SB: Merging step result with command result: {step.ExecutionContext.CommandResult.Value}"); - Trace.Info($"##DEBUG_SB: Before merge, step result: {step.ExecutionContext.Result}"); step.ExecutionContext.Result = TaskResultUtil.MergeTaskResults(step.ExecutionContext.Result, step.ExecutionContext.CommandResult.Value); } @@ -370,67 +361,12 @@ private async Task RunStepAsync(IStep step, CancellationToken jobCancellationTok } else { - // display status of TaskResult - try - { - Trace.Info($"##DEBUG_SB: TaskResult.Succeeded: {TaskResult.Succeeded}"); - } - catch (Exception ex) - { - Trace.Info($"##DEBUG_SB: Could not display TaskResult.Succeeded: {ex.Message}"); - } - try - { - Trace.Info($"##DEBUG_SB: TaskResult.SucceededWithIssues: {TaskResult.SucceededWithIssues}"); - } - catch (Exception ex) - { - Trace.Info($"##DEBUG_SB: Could not display TaskResult.SucceededWithIssues: {ex.Message}"); - } - try - { - Trace.Info($"##DEBUG_SB: TaskResult.Failed: {TaskResult.Failed}"); - } - catch (Exception ex) - { - Trace.Info($"##DEBUG_SB: Could not display TaskResult.Failed: {ex.Message}"); - } - try - { - Trace.Info($"##DEBUG_SB: TaskResult.Canceled: {TaskResult.Canceled}"); - } - catch (Exception ex) - { - Trace.Info($"##DEBUG_SB: Could not display TaskResult.Canceled: {ex.Message}"); - } - try - { - Trace.Info($"##DEBUG_SB: TaskResult.Skipped: {TaskResult.Skipped}"); - } - catch (Exception ex) - { - Trace.Info($"##DEBUG_SB: Could not display TaskResult.Skipped: {ex.Message}"); - } - try - { - Trace.Info($"##DEBUG_SB: TaskResult.Abandoned: {TaskResult.Abandoned}"); - } - catch (Exception ex) - { - Trace.Info($"##DEBUG_SB: Could not display TaskResult.Abandoned: {ex.Message}"); - } - - Trace.Info($"Step result: {step.ExecutionContext.Result}"); } // Complete the step context. - Trace.Info("##DEBUG_SB: Finishing step in RunStepAsync."); - Trace.Info($"##DEBUG_SB: check1 Step result: {step.ExecutionContext.Result}"); step.ExecutionContext.Section(StringUtil.Loc("StepFinishing", step.DisplayName)); - Trace.Info($"##DEBUG_SB: check2 Step result: {step.ExecutionContext.Result}"); step.ExecutionContext.Complete(); - Trace.Info($"##DEBUG_SB: check3 Step result: {step.ExecutionContext.Result}"); } private async Task SwitchToUtf8Codepage(IStep step) diff --git a/src/Agent.Worker/TaskRunner.cs b/src/Agent.Worker/TaskRunner.cs index 4cfee6d9b2..8d50526c4c 100644 --- a/src/Agent.Worker/TaskRunner.cs +++ b/src/Agent.Worker/TaskRunner.cs @@ -419,8 +419,6 @@ private async Task RunAsyncInternal() if (enableResourceUtilizationWarnings) { - // add tracing statement to indicate that resource utilization warnings are enabled - Trace.Info("##DEBUG_SB: Resource utilization warnings are enabled."); _ = resourceDiagnosticManager.RunMemoryUtilizationMonitorAsync(); _ = resourceDiagnosticManager.RunDiskSpaceUtilizationMonitorAsync(); _ = resourceDiagnosticManager.RunCpuUtilizationMonitorAsync(Task.Reference.Id.ToString()); From 192ed66e8a68d21a07071cc718af20ffac59ef86 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Mon, 6 Jan 2025 14:48:03 +0530 Subject: [PATCH 43/51] removed tracings from process invoker and resource metrics manager --- src/Agent.Sdk/ProcessInvoker.cs | 42 +----------- src/Agent.Worker/ResourceMetricsManager.cs | 76 ---------------------- 2 files changed, 2 insertions(+), 116 deletions(-) diff --git a/src/Agent.Sdk/ProcessInvoker.cs b/src/Agent.Sdk/ProcessInvoker.cs index 333f63cca1..d372132bf6 100644 --- a/src/Agent.Sdk/ProcessInvoker.cs +++ b/src/Agent.Sdk/ProcessInvoker.cs @@ -253,17 +253,13 @@ public async Task ExecuteAsync( // Ensure we process STDERR even the process exit event happen before we start read STDERR stream. if (_proc.StartInfo.RedirectStandardError) { - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Before incrementing _asyncStreamReaderCount for STDERR: {_asyncStreamReaderCount}"); Interlocked.Increment(ref _asyncStreamReaderCount); - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] After incrementing _asyncStreamReaderCount for STDERR: {_asyncStreamReaderCount}"); } // Ensure we process STDOUT even the process exit event happen before we start read STDOUT stream. if (_proc.StartInfo.RedirectStandardOutput) { - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Before incrementing _asyncStreamReaderCount for STDOUT: {_asyncStreamReaderCount}"); Interlocked.Increment(ref _asyncStreamReaderCount); - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] After incrementing _asyncStreamReaderCount for STDOUT: {_asyncStreamReaderCount}"); } // If StandardErrorEncoding or StandardOutputEncoding is not specified the on the @@ -336,12 +332,10 @@ public async Task ExecuteAsync( AsyncManualResetEvent afterCancelKillProcessTreeAttemptSignal = new AsyncManualResetEvent(); using (var registration = cancellationToken.Register(async () => { - Trace.Info($"##DEBUG_SB: Cancellation requested, attempting to cancel and kill process tree for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); await CancelAndKillProcessTree(killProcessOnCancel); // signal to ensure we exit the loop after we attempt to cancel and kill the process tree (which is best effort) afterCancelKillProcessTreeAttemptSignal.Set(); - Trace.Info($"##DEBUG_SB: Cancellation requested, process tree killed for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); })) { Trace.Info($"Process started with process id {_proc.Id}, waiting for process exit."); @@ -350,33 +344,24 @@ public async Task ExecuteAsync( { Task outputSignal = _outputProcessEvent.WaitAsync(); Task[] tasks; - Trace.Info($"##DEBUG_SB: whiletrueblock_processinvoker using block for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); if (continueAfterCancelProcessTreeKillAttempt) { - Trace.Info($"##DEBUG_SB: PInvokerA for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); tasks = new Task[] { outputSignal, _processExitedCompletionSource.Task, afterCancelKillProcessTreeAttemptSignal.WaitAsync() }; - Trace.Info($"##DEBUG_SB: PInvokerB for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); } else { - Trace.Info($"##DEBUG_SB: PInvokerC for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); tasks = new Task[] { outputSignal, _processExitedCompletionSource.Task }; - Trace.Info($"##DEBUG_SB: PInvokerD for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); } - Trace.Info($"##DEBUG_SB: before signaled await for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); var signaled = await Task.WhenAny(tasks); - Trace.Info($"##DEBUG_SB: after signaled await for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); if (signaled == outputSignal) { - Trace.Info($"##DEBUG_SB: ProcessOutput if signaled == outputSignal for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); ProcessOutput(); } else { - Trace.Info($"##DEBUG_SB: ProcessOutput if signaled != outputSignal for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); _stopWatch.Stop(); break; } @@ -384,7 +369,6 @@ public async Task ExecuteAsync( // Just in case there was some pending output when the process shut down go ahead and check the // data buffers one last time before returning - Trace.Info($"##DEBUG_SB: ProcessOutput before exit for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); ProcessOutput(); if (_proc.HasExited) @@ -420,9 +404,11 @@ protected virtual void Dispose(bool disposing) { if (_proc != null) { + //Dispose the standard input/output/error stream. Refer: https://github.com/dotnet/runtime/issues/58872 _proc.StandardInput.Dispose(); _proc.StandardOutput.Dispose(); _proc.StandardError.Dispose(); + _proc.Dispose(); _proc = null; } @@ -434,25 +420,20 @@ private void ProcessOutput() List errorData = new List(); List outputData = new List(); - Trace.Info($"##DEBUG_SB: before errorLine dequeue for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); string errorLine; while (_errorData.TryDequeue(out errorLine)) { errorData.Add(errorLine); } - Trace.Info($"##DEBUG_SB: before outputLine dequeue for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); string outputLine; while (_outputData.TryDequeue(out outputLine)) { outputData.Add(outputLine); } - Trace.Info($"##DEBUG_SB: Before reset thread info: Thread.CurrentThread.ManagedThreadId={Thread.CurrentThread.ManagedThreadId} for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); _outputProcessEvent.Reset(); - Trace.Info($"##DEBUG_SB: After reset thread info: Thread.CurrentThread.ManagedThreadId={Thread.CurrentThread.ManagedThreadId} for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); - Trace.Info($"##DEBUG_SB: Writing the error lines for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); // Write the error lines. if (errorData != null && this.ErrorDataReceived != null) { @@ -465,7 +446,6 @@ private void ProcessOutput() } } - Trace.Info($"##DEBUG_SB: Writing the output lines for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); // Process the output lines. if (outputData != null && this.OutputDataReceived != null) { @@ -482,13 +462,11 @@ private void ProcessOutput() internal protected virtual async Task CancelAndKillProcessTree(bool killProcessOnCancel) { - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Entering CancelAndKillProcessTree for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); bool gracefulShoutdown = TryUseGracefulShutdown && !killProcessOnCancel; ArgUtil.NotNull(_proc, nameof(_proc)); - Trace.Info($"##DEBUG_SB: Cancel and kill process tree for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); if (!killProcessOnCancel) { @@ -496,13 +474,11 @@ internal protected virtual async Task CancelAndKillProcessTree(bool killProcessO if (sigint_succeed) { Trace.Info("Process cancelled successfully through Ctrl+C/SIGINT."); - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree for process {_proc?.Id}."); return; } if (gracefulShoutdown) { - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree for process {_proc?.Id}."); return; } @@ -510,14 +486,12 @@ internal protected virtual async Task CancelAndKillProcessTree(bool killProcessO if (sigterm_succeed) { Trace.Info("Process terminate successfully through Ctrl+Break/SIGTERM."); - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree for process {_proc?.Id}."); return; } } Trace.Info("Kill entire process tree since both cancel and terminate signal has been ignored by the target process."); KillProcessTree(); - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting CancelAndKillProcessTree for process {_proc?.Id}."); } private async Task SendSIGINT(TimeSpan timeout) @@ -570,7 +544,6 @@ private void StartReadStream(StreamReader reader, ConcurrentQueue dataBu // try // { //add _proc.id info everywhere that thread id is being logged - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Start reading stream for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); while (!reader.EndOfStream) { string line = reader.ReadLine(); @@ -578,29 +551,18 @@ private void StartReadStream(StreamReader reader, ConcurrentQueue dataBu { if (DisableWorkerCommands) { - Trace.Info($"##DEBUG_SB: Deactivating VSO commands for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); line = StringUtil.DeactivateVsoCommands(line); } dataBuffer.Enqueue(line); - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] {bufferName} Enqueued line: {line} for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); _outputProcessEvent.Set(); } } - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] STDOUT/STDERR {bufferName} stream read finished for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); if (Interlocked.Decrement(ref _asyncStreamReaderCount) == 0 && _waitingOnStreams) { - Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] All stream readers finished. Setting process exited completion source for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); _processExitedCompletionSource.TrySetResult(true); } - // } - // catch { - // Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] caught exception in {bufferName} for process {_proc.Id}"); - // } - // finally { - // Trace.Info($"[Thread {Thread.CurrentThread.ManagedThreadId}] Exiting readstream {bufferName} for {_proc.Id}"); - // } }); } diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index 4ea20422c1..bab58c08cd 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -42,21 +42,10 @@ public sealed class ResourceMetricsManager : AgentService, IResourceMetricsManag private static CpuInfo _cpuInfo; private static DiskInfo _diskInfo; private static MemoryInfo _memoryInfo; - - - // private static readonly object _cpuInfoLastUpdatedLock = new object(); - // private static readonly object _diskInfoLastUpdatedLock = new object(); - // private static readonly object _memoryInfoLastUpdatedLock = new object(); - private static readonly object _cpuInfoLock = new object(); private static readonly object _diskInfoLock = new object(); private static readonly object _memoryInfoLock = new object(); - // private Task _cpuMonitorTask; - // private Task _memoryMonitorTask; - // private Task _diskMonitorTask; - // private readonly object _monitorLock = new object(); - #endregion #region MetricStructs @@ -127,13 +116,10 @@ private void PublishTelemetry(string message, string taskId) #region MetricMethods private async Task GetCpuInfoAsync(CancellationToken cancellationToken) { - // lock (_cpuInfoLastUpdatedLock) - // { if (_cpuInfo.Updated >= DateTime.Now - TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)) { return; } - // } if (PlatformUtil.RunningOnWindows) { @@ -206,7 +192,6 @@ await Task.Run(() => try { - Trace.Info($"##DEBUG_SB: CPU info - Getting CPU usage on MacOS from source: "); using var processInvoker = HostContext.CreateService(); List outputs = new List(); @@ -222,7 +207,6 @@ await Task.Run(() => var filePath = "/bin/bash"; var arguments = "-c \"top -l 2 -o cpu | grep ^CPU\""; - Trace.Info($"##DEBUG_SB: CPU info - Executing {filePath} {arguments}; source: "); await processInvoker.ExecuteAsync( workingDirectory: string.Empty, @@ -235,9 +219,7 @@ await processInvoker.ExecuteAsync( cancellationToken: cancellationToken); //try setting killProcessOnCancel to false // Use second sample for more accurate calculation - Trace.Info($"##DEBUG_SB: All Outputs in CPU Info block: {outputs}"); var cpuInfoIdle = double.Parse(outputs[1].Split(' ', (char)StringSplitOptions.RemoveEmptyEntries)[6].Trim('%')); - Trace.Info($"##DEBUG_SB: CPU Info Idle: {cpuInfoIdle}"); lock (_cpuInfoLock) { @@ -257,14 +239,10 @@ await processInvoker.ExecuteAsync( private void GetDiskInfo() { - Trace.Info($"##DEBUG_SB: Getting disk info from source: "); - // lock (_diskInfoLastUpdatedLock) - // { if (_diskInfo.Updated >= DateTime.Now - TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)) { return; } - // } string root = Path.GetPathRoot(_context.GetVariableValueOrDefault(Constants.Variables.Agent.WorkFolder)); var driveInfo = new DriveInfo(root); @@ -280,13 +258,10 @@ private void GetDiskInfo() private async Task GetMemoryInfoAsync(CancellationToken cancellationToken) { - // lock (_memoryInfoLastUpdatedLock) - // { if (_memoryInfo.Updated >= DateTime.Now - TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)) { return; } - // } if (PlatformUtil.RunningOnWindows) { @@ -344,7 +319,6 @@ await Task.Run(() => // but unfortunately it returns values in pages and has no built-in arguments for custom output // so we need to parse and cast the output manually - Trace.Info($"##DEBUG_SB: Getting memory info on MacOS from source: "); using var processInvoker = HostContext.CreateService(); List outputs = new List(); @@ -359,7 +333,6 @@ await Task.Run(() => }; var filePath = "vm_stat"; - Trace.Info($"##DEBUG_SB: Memory info - Executing {filePath}; statement source: "); await processInvoker.ExecuteAsync( workingDirectory: string.Empty, @@ -371,7 +344,6 @@ await processInvoker.ExecuteAsync( killProcessOnCancel: true, cancellationToken: cancellationToken); - Trace.Info($"##DEBUG_SB: All Outputs in Memory Info block: {outputs}"); var pageSize = int.Parse(outputs[0].Split(" ", StringSplitOptions.RemoveEmptyEntries)[7]); @@ -385,8 +357,6 @@ await processInvoker.ExecuteAsync( var freeMemory = (pagesFree + pagesInactive) * pageSize; var usedMemory = (pagesActive + pagesSpeculative + pagesWiredDown + pagesOccupied) * pageSize; - Trace.Info($"##DEBUG_SB: Free Memory: {freeMemory}"); - Trace.Info($"##DEBUG_SB: Used Memory: {usedMemory}"); lock (_memoryInfoLock) { @@ -459,7 +429,6 @@ private async Task GetMemoryInfoStringAsync(CancellationToken cancellati #region MonitorLoops public async Task RunDebugResourceMonitorAsync() { - Trace.Info("##DEBUG_SB: Starting debug resource monitor"); while (!_context.CancellationToken.IsCancellationRequested) { using var timeoutTokenSource = new CancellationTokenSource(); @@ -469,22 +438,17 @@ public async Task RunDebugResourceMonitorAsync() _context.CancellationToken, timeoutTokenSource.Token); - Trace.Info("##DEBUG_SB: Debug Resource Monitor"); _context.Debug(StringUtil.Loc("ResourceMonitorAgentEnvironmentResource", GetDiskInfoString(), await GetMemoryInfoStringAsync(linkedTokenSource.Token), await GetCpuInfoStringAsync(linkedTokenSource.Token))); - Trace.Info($"##DEBUG_SB: Waiting for {ACTIVE_MODE_INTERVAL} ms"); await Task.Delay(ACTIVE_MODE_INTERVAL, _context.CancellationToken); - Trace.Info($"##DEBUG_SB: Done waiting for {ACTIVE_MODE_INTERVAL} ms"); } - Trace.Info("##DEBUG_SB: Exiting debug resource monitor"); } public async Task RunDiskSpaceUtilizationMonitorAsync() { - Trace.Info("##DEBUG_SB: Starting disk space utilization monitor"); while (!_context.CancellationToken.IsCancellationRequested) { try @@ -496,7 +460,6 @@ public async Task RunDiskSpaceUtilizationMonitorAsync() if (freeDiskSpacePercentage <= AVAILABLE_DISK_SPACE_PERCENTAGE_THRESHOLD) { - Trace.Info("##DEBUG_SB: ResourceMonitorFreeDiskSpaceIsLowerThanThreshold, context.Warning called"); _context.Warning(StringUtil.Loc("ResourceMonitorFreeDiskSpaceIsLowerThanThreshold", _diskInfo.VolumeRoot, AVAILABLE_DISK_SPACE_PERCENTAGE_THRESHOLD, @@ -512,18 +475,13 @@ public async Task RunDiskSpaceUtilizationMonitorAsync() break; } - Trace.Info($"##DEBUG_SB: Disk Space Utilization - Waiting for {WARNING_MESSAGE_INTERVAL} ms"); var isCancelled = _context.CancellationToken.IsCancellationRequested; - Trace.Info($"##DEBUG_SB: Disk Space Utilization - Is Cancellation Requested, Before Task.Delay: {isCancelled}"); await Task.Delay(WARNING_MESSAGE_INTERVAL, _context.CancellationToken); - Trace.Info($"##DEBUG_SB: Disk Space Utilization - Done waiting for {WARNING_MESSAGE_INTERVAL} ms"); } - Trace.Info("##DEBUG_SB: Exiting disk space utilization monitor"); } public async Task RunMemoryUtilizationMonitorAsync() { - Trace.Info("##DEBUG_SB: Starting memory utilization monitor"); int iterationCount = 0; while (!_context.CancellationToken.IsCancellationRequested) { @@ -536,7 +494,6 @@ public async Task RunMemoryUtilizationMonitorAsync() timeoutTokenSource.Token); // display cancellation token and properties - Trace.Info($"##DEBUG_SB: Memory Utilization - CancellationToken: {linkedTokenSource.Token}"); try { @@ -546,7 +503,6 @@ public async Task RunMemoryUtilizationMonitorAsync() if (100.0 - usedMemoryPercentage <= AVAILABLE_MEMORY_PERCENTAGE_THRESHOLD) { - Trace.Info("##DEBUG_SB: ResourceMonitorMemorySpaceIsLowerThanThreshold, context.Warning called"); _context.Warning(StringUtil.Loc("ResourceMonitorMemorySpaceIsLowerThanThreshold", AVAILABLE_MEMORY_PERCENTAGE_THRESHOLD, $"{usedMemoryPercentage:0.00}")); @@ -561,19 +517,14 @@ public async Task RunMemoryUtilizationMonitorAsync() break; } - Trace.Info($"##DEBUG_SB: Memory Utilization - Waiting for {WARNING_MESSAGE_INTERVAL} ms, iteration count: {iterationCount}"); var isCancelled = _context.CancellationToken.IsCancellationRequested; - Trace.Info($"##DEBUG_SB: Memory Utilization - Is Cancellation Requested, Before Task.Delay: {isCancelled}"); await Task.Delay(WARNING_MESSAGE_INTERVAL, _context.CancellationToken); - Trace.Info($"##DEBUG_SB: Memory Utilization - Done waiting for {WARNING_MESSAGE_INTERVAL} ms, iteration count: {iterationCount}"); } - Trace.Info("##DEBUG_SB: Exiting memory utilization monitor"); } public async Task RunCpuUtilizationMonitorAsync(string taskId) { - Trace.Info("##DEBUG_SB: Starting CPU utilization monitor"); int iterationCount = 0; while (!_context.CancellationToken.IsCancellationRequested) { @@ -585,7 +536,6 @@ public async Task RunCpuUtilizationMonitorAsync(string taskId) _context.CancellationToken, timeoutTokenSource.Token); - Trace.Info($"##DEBUG_SB: CPU Utilization - CancellationToken: {linkedTokenSource.Token}"); try { @@ -595,8 +545,6 @@ public async Task RunCpuUtilizationMonitorAsync(string taskId) { string message = $"CPU utilization is higher than {CPU_UTILIZATION_PERCENTAGE_THRESHOLD}%; currently used: {_cpuInfo.Usage:0.00}%"; - // Trace.Info($"##DEBUG_SB: CPU Utilization instead of publishTelemetry - {message}"); - //commented out PublishTelemetry for now PublishTelemetry(message, taskId); break; @@ -610,36 +558,12 @@ public async Task RunCpuUtilizationMonitorAsync(string taskId) break; } - Trace.Info($"##DEBUG_SB: CPU Utilization - Waiting for {WARNING_MESSAGE_INTERVAL} ms, taskid: {taskId}, iteration count: {iterationCount}"); //check if cancellation token has been cancelled var isCancelled = _context.CancellationToken.IsCancellationRequested; - Trace.Info($"##DEBUG_SB: CPU Utilization - Is Cancellation Requested, Before Task.Delay: {isCancelled}"); await Task.Delay(WARNING_MESSAGE_INTERVAL, _context.CancellationToken); - Trace.Info($"##DEBUG_SB: CPU Utilization - Done waiting for {WARNING_MESSAGE_INTERVAL} ms, taskid: {taskId}, iteration count: {iterationCount}"); } - Trace.Info("##DEBUG_SB: Exiting CPU utilization monitor"); } - // public void StartMonitors(string taskId) - // { - // lock (_monitorLock) - // { - // if (_cpuMonitorTask == null || _cpuMonitorTask.IsCompleted) - // { - // _cpuMonitorTask = RunCpuUtilizationMonitorAsync(taskId); - // } - - // if (_memoryMonitorTask == null || _memoryMonitorTask.IsCompleted) - // { - // _memoryMonitorTask = RunMemoryUtilizationMonitorAsync(); - // } - - // if (_diskMonitorTask == null || _diskMonitorTask.IsCompleted) - // { - // _diskMonitorTask = RunDiskSpaceUtilizationMonitorAsync(); - // } - // } - // } #endregion } } From d6797a3a104dc280d35993dd8afb2657d914d3ca Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Mon, 6 Jan 2025 15:02:02 +0530 Subject: [PATCH 44/51] remove temporary debug statements --- src/Agent.Sdk/ProcessInvoker.cs | 18 +++++------------- src/Agent.Worker/ResourceMetricsManager.cs | 14 +------------- 2 files changed, 6 insertions(+), 26 deletions(-) diff --git a/src/Agent.Sdk/ProcessInvoker.cs b/src/Agent.Sdk/ProcessInvoker.cs index d372132bf6..324765146f 100644 --- a/src/Agent.Sdk/ProcessInvoker.cs +++ b/src/Agent.Sdk/ProcessInvoker.cs @@ -307,13 +307,13 @@ public async Task ExecuteAsync( // Start the standard error notifications, if appropriate. if (_proc.StartInfo.RedirectStandardError) { - StartReadStream(_proc.StandardError, _errorData, "STDERR1"); + StartReadStream(_proc.StandardError, _errorData); } // Start the standard output notifications, if appropriate. if (_proc.StartInfo.RedirectStandardOutput) { - StartReadStream(_proc.StandardOutput, _outputData, "STDOUTPUT1"); + StartReadStream(_proc.StandardOutput, _outputData); } if (_proc.StartInfo.RedirectStandardInput) @@ -462,12 +462,9 @@ private void ProcessOutput() internal protected virtual async Task CancelAndKillProcessTree(bool killProcessOnCancel) { - bool gracefulShoutdown = TryUseGracefulShutdown && !killProcessOnCancel; ArgUtil.NotNull(_proc, nameof(_proc)); - - if (!killProcessOnCancel) { bool sigint_succeed = await SendSIGINT(SigintTimeout); @@ -517,8 +514,6 @@ private async Task SendSIGTERM(TimeSpan timeout) private void ProcessExitedHandler(object sender, EventArgs e) { Trace.Info($"Exited process {_proc.Id} with exit code {_proc.ExitCode}"); - - // if ((_proc.StartInfo.RedirectStandardError || _proc.StartInfo.RedirectStandardOutput) && Interlocked.CompareExchange(ref _asyncStreamReaderCount, 0, 0) > 0) if ((_proc.StartInfo.RedirectStandardError || _proc.StartInfo.RedirectStandardOutput) && _asyncStreamReaderCount != 0) { _waitingOnStreams = true; @@ -537,13 +532,10 @@ private void ProcessExitedHandler(object sender, EventArgs e) } } - private void StartReadStream(StreamReader reader, ConcurrentQueue dataBuffer, string bufferName) + private void StartReadStream(StreamReader reader, ConcurrentQueue dataBuffer) { Task.Run(() => { - // try - // { - //add _proc.id info everywhere that thread id is being logged while (!reader.EndOfStream) { string line = reader.ReadLine(); @@ -557,7 +549,7 @@ private void StartReadStream(StreamReader reader, ConcurrentQueue dataBu _outputProcessEvent.Set(); } } - + Trace.Info("STDOUT/STDERR stream read finished."); if (Interlocked.Decrement(ref _asyncStreamReaderCount) == 0 && _waitingOnStreams) { @@ -587,7 +579,7 @@ private void StartWriteStream(InputQueue redirectStandardIn, StreamWrite if (!keepStandardInOpen) { - Trace.Info($"Close STDIN after the first redirect finished. for process {_proc.Id} that has filename {_proc.StartInfo.FileName}."); + Trace.Info($"Close STDIN after the first redirect finished."); standardIn.Close(); break; } diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index bab58c08cd..9072b3e4b6 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -24,7 +24,6 @@ public interface IResourceMetricsManager : IAgentService Task RunDiskSpaceUtilizationMonitorAsync(); Task RunCpuUtilizationMonitorAsync(string taskId); void SetContext(IExecutionContext context); - // void StartMonitors(string taskId); } public sealed class ResourceMetricsManager : AgentService, IResourceMetricsManager @@ -42,10 +41,10 @@ public sealed class ResourceMetricsManager : AgentService, IResourceMetricsManag private static CpuInfo _cpuInfo; private static DiskInfo _diskInfo; private static MemoryInfo _memoryInfo; + private static readonly object _cpuInfoLock = new object(); private static readonly object _diskInfoLock = new object(); private static readonly object _memoryInfoLock = new object(); - #endregion #region MetricStructs @@ -475,17 +474,14 @@ public async Task RunDiskSpaceUtilizationMonitorAsync() break; } - var isCancelled = _context.CancellationToken.IsCancellationRequested; await Task.Delay(WARNING_MESSAGE_INTERVAL, _context.CancellationToken); } } public async Task RunMemoryUtilizationMonitorAsync() { - int iterationCount = 0; while (!_context.CancellationToken.IsCancellationRequested) { - iterationCount++; using var timeoutTokenSource = new CancellationTokenSource(); timeoutTokenSource.CancelAfter(TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)); @@ -493,8 +489,6 @@ public async Task RunMemoryUtilizationMonitorAsync() _context.CancellationToken, timeoutTokenSource.Token); - // display cancellation token and properties - try { await GetMemoryInfoAsync(linkedTokenSource.Token); @@ -517,7 +511,6 @@ public async Task RunMemoryUtilizationMonitorAsync() break; } - var isCancelled = _context.CancellationToken.IsCancellationRequested; await Task.Delay(WARNING_MESSAGE_INTERVAL, _context.CancellationToken); } @@ -525,10 +518,8 @@ public async Task RunMemoryUtilizationMonitorAsync() public async Task RunCpuUtilizationMonitorAsync(string taskId) { - int iterationCount = 0; while (!_context.CancellationToken.IsCancellationRequested) { - iterationCount++; using var timeoutTokenSource = new CancellationTokenSource(); timeoutTokenSource.CancelAfter(TimeSpan.FromMilliseconds(METRICS_UPDATE_INTERVAL)); @@ -558,12 +549,9 @@ public async Task RunCpuUtilizationMonitorAsync(string taskId) break; } - //check if cancellation token has been cancelled - var isCancelled = _context.CancellationToken.IsCancellationRequested; await Task.Delay(WARNING_MESSAGE_INTERVAL, _context.CancellationToken); } } - #endregion } } From abaacf0a5001fcda9c8d8a4a60e4a71596249e33 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Mon, 6 Jan 2025 15:05:51 +0530 Subject: [PATCH 45/51] remove temporary debug statements --- src/Agent.Sdk/ProcessInvoker.cs | 3 ++- src/Agent.Worker/ResourceMetricsManager.cs | 3 --- 2 files changed, 2 insertions(+), 4 deletions(-) diff --git a/src/Agent.Sdk/ProcessInvoker.cs b/src/Agent.Sdk/ProcessInvoker.cs index 324765146f..9de4838262 100644 --- a/src/Agent.Sdk/ProcessInvoker.cs +++ b/src/Agent.Sdk/ProcessInvoker.cs @@ -549,6 +549,7 @@ private void StartReadStream(StreamReader reader, ConcurrentQueue dataBu _outputProcessEvent.Set(); } } + Trace.Info("STDOUT/STDERR stream read finished."); if (Interlocked.Decrement(ref _asyncStreamReaderCount) == 0 && _waitingOnStreams) @@ -579,7 +580,7 @@ private void StartWriteStream(InputQueue redirectStandardIn, StreamWrite if (!keepStandardInOpen) { - Trace.Info($"Close STDIN after the first redirect finished."); + Trace.Info("Close STDIN after the first redirect finished."); standardIn.Close(); break; } diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index 9072b3e4b6..6d684fd57f 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -368,7 +368,6 @@ await processInvoker.ExecuteAsync( { lock (_memoryInfoLock) { - _memoryInfo.IsProcRunning = false; } } @@ -513,7 +512,6 @@ public async Task RunMemoryUtilizationMonitorAsync() await Task.Delay(WARNING_MESSAGE_INTERVAL, _context.CancellationToken); } - } public async Task RunCpuUtilizationMonitorAsync(string taskId) @@ -527,7 +525,6 @@ public async Task RunCpuUtilizationMonitorAsync(string taskId) _context.CancellationToken, timeoutTokenSource.Token); - try { await GetCpuInfoAsync(linkedTokenSource.Token); From d69d4a2441f83a6e33b6bfcdcfff9e2e421f09f5 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Mon, 6 Jan 2025 16:15:05 +0530 Subject: [PATCH 46/51] formatting changes --- src/Agent.Worker/ResourceMetricsManager.cs | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index 6d684fd57f..908462f383 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -216,7 +216,6 @@ await processInvoker.ExecuteAsync( outputEncoding: null, killProcessOnCancel: true, cancellationToken: cancellationToken); - //try setting killProcessOnCancel to false // Use second sample for more accurate calculation var cpuInfoIdle = double.Parse(outputs[1].Split(' ', (char)StringSplitOptions.RemoveEmptyEntries)[6].Trim('%')); @@ -230,7 +229,7 @@ await processInvoker.ExecuteAsync( { lock (_cpuInfoLock) { - _cpuInfo.IsProcRunning= false; + _cpuInfo.IsProcRunning = false; } } } From 64036d25fe8605ad0ebe409c01463fa75b6903dd Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Tue, 7 Jan 2025 16:14:51 +0530 Subject: [PATCH 47/51] formatting changes --- src/Agent.Worker/ResourceMetricsManager.cs | 16 ++++++++++------ 1 file changed, 10 insertions(+), 6 deletions(-) diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index 908462f383..a1ffb73742 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -185,12 +185,15 @@ await Task.Run(() => { lock (_cpuInfoLock) { - if (_cpuInfo.IsProcRunning) return; + if (_cpuInfo.IsProcRunning) + { + return; + } _cpuInfo.IsProcRunning = true; } + try { - using var processInvoker = HostContext.CreateService(); List outputs = new List(); @@ -307,12 +310,15 @@ await Task.Run(() => { lock (_memoryInfoLock) { - if (_memoryInfo.IsProcRunning) return; + if (_memoryInfo.IsProcRunning) + { + return; + } _memoryInfo.IsProcRunning = true; } + try { - // vm_stat allows to get the most detailed information about memory usage on MacOS // but unfortunately it returns values in pages and has no built-in arguments for custom output // so we need to parse and cast the output manually @@ -342,7 +348,6 @@ await processInvoker.ExecuteAsync( killProcessOnCancel: true, cancellationToken: cancellationToken); - var pageSize = int.Parse(outputs[0].Split(" ", StringSplitOptions.RemoveEmptyEntries)[7]); var pagesFree = long.Parse(outputs[1].Split(" ", StringSplitOptions.RemoveEmptyEntries)[2].Trim('.')); @@ -355,7 +360,6 @@ await processInvoker.ExecuteAsync( var freeMemory = (pagesFree + pagesInactive) * pageSize; var usedMemory = (pagesActive + pagesSpeculative + pagesWiredDown + pagesOccupied) * pageSize; - lock (_memoryInfoLock) { _memoryInfo.Updated = DateTime.Now; From 016540c7b04d9f0043878b9580e64540fda7570f Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Wed, 8 Jan 2025 15:20:46 +0530 Subject: [PATCH 48/51] try-catch in dispose --- src/Agent.Sdk/ProcessInvoker.cs | 29 ++++++++++++++++++++++++++--- 1 file changed, 26 insertions(+), 3 deletions(-) diff --git a/src/Agent.Sdk/ProcessInvoker.cs b/src/Agent.Sdk/ProcessInvoker.cs index 9de4838262..0e32810cb3 100644 --- a/src/Agent.Sdk/ProcessInvoker.cs +++ b/src/Agent.Sdk/ProcessInvoker.cs @@ -405,9 +405,32 @@ protected virtual void Dispose(bool disposing) if (_proc != null) { //Dispose the standard input/output/error stream. Refer: https://github.com/dotnet/runtime/issues/58872 - _proc.StandardInput.Dispose(); - _proc.StandardOutput.Dispose(); - _proc.StandardError.Dispose(); + try + { + _proc.StandardInput.Dispose(); + } + catch (Exception ex) + { + Trace.Info($"Skipping _proc.StandardInput.Dispose() due to exception {ex}"); + } + + try + { + _proc.StandardOutput.Dispose(); + } + catch (Exception ex) + { + Trace.Info($"Skipping _proc.StandardOutput.Dispose() due to exception {ex}"); + } + + try + { + _proc.StandardError.Dispose(); + } + catch (Exception ex) + { + Trace.Info($"Skipping _proc.StandardError.Dispose() due to exception {ex}"); + } _proc.Dispose(); _proc = null; From 519c0acc358cfe30f14adc735275d48aee05fe8d Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Thu, 9 Jan 2025 11:02:57 +0530 Subject: [PATCH 49/51] null check for proc.stdout and proc.stderr, isprocrunning for diskinfo and isprocrunning check for all OS options --- src/Agent.Sdk/ProcessInvoker.cs | 30 +-- src/Agent.Worker/ResourceMetricsManager.cs | 243 +++++++++++---------- 2 files changed, 136 insertions(+), 137 deletions(-) diff --git a/src/Agent.Sdk/ProcessInvoker.cs b/src/Agent.Sdk/ProcessInvoker.cs index 0e32810cb3..f4861cde1d 100644 --- a/src/Agent.Sdk/ProcessInvoker.cs +++ b/src/Agent.Sdk/ProcessInvoker.cs @@ -404,33 +404,9 @@ protected virtual void Dispose(bool disposing) { if (_proc != null) { - //Dispose the standard input/output/error stream. Refer: https://github.com/dotnet/runtime/issues/58872 - try - { - _proc.StandardInput.Dispose(); - } - catch (Exception ex) - { - Trace.Info($"Skipping _proc.StandardInput.Dispose() due to exception {ex}"); - } - - try - { - _proc.StandardOutput.Dispose(); - } - catch (Exception ex) - { - Trace.Info($"Skipping _proc.StandardOutput.Dispose() due to exception {ex}"); - } - - try - { - _proc.StandardError.Dispose(); - } - catch (Exception ex) - { - Trace.Info($"Skipping _proc.StandardError.Dispose() due to exception {ex}"); - } + //Dispose the standard output/error stream. Refer: https://github.com/dotnet/runtime/issues/58872 + _proc.StandardOutput?.Dispose(); + _proc.StandardError?.Dispose(); _proc.Dispose(); _proc = null; diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index a1ffb73742..40ef3a8241 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -57,6 +57,7 @@ private struct CpuInfo private struct DiskInfo { + public bool IsProcRunning; public DateTime Updated; public double TotalDiskSpaceMB; public double FreeDiskSpaceMB; @@ -120,79 +121,80 @@ private async Task GetCpuInfoAsync(CancellationToken cancellationToken) return; } - if (PlatformUtil.RunningOnWindows) + lock (_cpuInfoLock) { - await Task.Run(() => + if (_cpuInfo.IsProcRunning) { - using var query = new ManagementObjectSearcher("SELECT PercentIdleTime FROM Win32_PerfFormattedData_PerfOS_Processor WHERE Name=\"_Total\""); - - ManagementObject cpuInfo = query.Get().OfType().FirstOrDefault() ?? throw new Exception("Failed to execute WMI query"); - var cpuInfoIdle = Convert.ToDouble(cpuInfo["PercentIdleTime"]); - - lock (_cpuInfoLock) - { - _cpuInfo.Updated = DateTime.Now; - _cpuInfo.Usage = 100 - cpuInfoIdle; - } - }, cancellationToken); + return; + } + _cpuInfo.IsProcRunning = true; } - if (PlatformUtil.RunningOnLinux) + try { - List samples = new(); - int samplesCount = 10; - - // /proc/stat updates linearly in real time and shows CPU time counters during the whole system uptime - // so we need to collect multiple samples to calculate CPU usage - for (int i = 0; i < samplesCount + 1; i++) + if (PlatformUtil.RunningOnWindows) { - string[] strings = await File.ReadAllLinesAsync("/proc/stat", cancellationToken); - if (cancellationToken.IsCancellationRequested) + await Task.Run(() => { - return; - } + using var query = new ManagementObjectSearcher("SELECT PercentIdleTime FROM Win32_PerfFormattedData_PerfOS_Processor WHERE Name=\"_Total\""); - samples.Add(strings[0] - .Split(' ', StringSplitOptions.RemoveEmptyEntries) - .Skip(1) - .Select(float.Parse) - .ToArray()); + ManagementObject cpuInfo = query.Get().OfType().FirstOrDefault() ?? throw new Exception("Failed to execute WMI query"); + var cpuInfoIdle = Convert.ToDouble(cpuInfo["PercentIdleTime"]); - await Task.Delay(100, cancellationToken); + lock (_cpuInfoLock) + { + _cpuInfo.Updated = DateTime.Now; + _cpuInfo.Usage = 100 - cpuInfoIdle; + } + }, cancellationToken); } - // The CPU time counters in the /proc/stat are: - // user, nice, system, idle, iowait, irq, softirq, steal, guest, guest_nice - // - // We need to get deltas for idle and total CPU time using the gathered samples - // and calculate the average to provide the CPU utilization in the moment - double cpuUsage = 0.0; - for (int i = 1; i < samplesCount + 1; i++) + if (PlatformUtil.RunningOnLinux) { - double idle = samples[i][3] - samples[i - 1][3]; - double total = samples[i].Sum() - samples[i - 1].Sum(); + List samples = new(); + int samplesCount = 10; - cpuUsage += 1.0 - (idle / total); - } + // /proc/stat updates linearly in real time and shows CPU time counters during the whole system uptime + // so we need to collect multiple samples to calculate CPU usage + for (int i = 0; i < samplesCount + 1; i++) + { + string[] strings = await File.ReadAllLinesAsync("/proc/stat", cancellationToken); + if (cancellationToken.IsCancellationRequested) + { + return; + } - lock (_cpuInfoLock) - { - _cpuInfo.Updated = DateTime.Now; - _cpuInfo.Usage = (cpuUsage / samplesCount) * 100; - } - } - if (PlatformUtil.RunningOnMacOS) - { - lock (_cpuInfoLock) - { - if (_cpuInfo.IsProcRunning) + samples.Add(strings[0] + .Split(' ', StringSplitOptions.RemoveEmptyEntries) + .Skip(1) + .Select(float.Parse) + .ToArray()); + + await Task.Delay(100, cancellationToken); + } + + // The CPU time counters in the /proc/stat are: + // user, nice, system, idle, iowait, irq, softirq, steal, guest, guest_nice + // + // We need to get deltas for idle and total CPU time using the gathered samples + // and calculate the average to provide the CPU utilization in the moment + double cpuUsage = 0.0; + for (int i = 1; i < samplesCount + 1; i++) { - return; + double idle = samples[i][3] - samples[i - 1][3]; + double total = samples[i].Sum() - samples[i - 1].Sum(); + + cpuUsage += 1.0 - (idle / total); + } + + lock (_cpuInfoLock) + { + _cpuInfo.Updated = DateTime.Now; + _cpuInfo.Usage = (cpuUsage / samplesCount) * 100; } - _cpuInfo.IsProcRunning = true; } - try + if (PlatformUtil.RunningOnMacOS) { using var processInvoker = HostContext.CreateService(); @@ -228,14 +230,15 @@ await processInvoker.ExecuteAsync( _cpuInfo.Usage = 100 - cpuInfoIdle; } } - finally + } + finally + { + lock (_cpuInfoLock) { - lock (_cpuInfoLock) - { - _cpuInfo.IsProcRunning = false; - } + _cpuInfo.IsProcRunning = false; } } + } private void GetDiskInfo() @@ -245,15 +248,34 @@ private void GetDiskInfo() return; } - string root = Path.GetPathRoot(_context.GetVariableValueOrDefault(Constants.Variables.Agent.WorkFolder)); - var driveInfo = new DriveInfo(root); - lock (_diskInfoLock) { - _diskInfo.Updated = DateTime.Now; - _diskInfo.TotalDiskSpaceMB = (double)driveInfo.TotalSize / 1048576; - _diskInfo.FreeDiskSpaceMB = (double)driveInfo.AvailableFreeSpace / 1048576; - _diskInfo.VolumeRoot = root; + if (_diskInfo.IsProcRunning) + { + return; + } + _diskInfo.IsProcRunning = true; + } + + try + { + string root = Path.GetPathRoot(_context.GetVariableValueOrDefault(Constants.Variables.Agent.WorkFolder)); + var driveInfo = new DriveInfo(root); + + lock (_diskInfoLock) + { + _diskInfo.Updated = DateTime.Now; + _diskInfo.TotalDiskSpaceMB = (double)driveInfo.TotalSize / 1048576; + _diskInfo.FreeDiskSpaceMB = (double)driveInfo.AvailableFreeSpace / 1048576; + _diskInfo.VolumeRoot = root; + } + } + finally + { + lock (_diskInfoLock) + { + _diskInfo.IsProcRunning = false; + } } } @@ -264,60 +286,60 @@ private async Task GetMemoryInfoAsync(CancellationToken cancellationToken) return; } - if (PlatformUtil.RunningOnWindows) + lock (_memoryInfoLock) { - await Task.Run(() => + if (_memoryInfo.IsProcRunning) { - using var query = new ManagementObjectSearcher("SELECT FreePhysicalMemory, TotalVisibleMemorySize FROM CIM_OperatingSystem"); - - ManagementObject memoryInfo = query.Get().OfType().FirstOrDefault() ?? throw new Exception("Failed to execute WMI query"); - var freeMemory = Convert.ToInt64(memoryInfo["FreePhysicalMemory"]); - var totalMemory = Convert.ToInt64(memoryInfo["TotalVisibleMemorySize"]); - - lock (_memoryInfoLock) - { - _memoryInfo.Updated = DateTime.Now; - _memoryInfo.TotalMemoryMB = totalMemory / 1024; - _memoryInfo.UsedMemoryMB = (totalMemory - freeMemory) / 1024; - } - }, cancellationToken); + return; + } + _memoryInfo.IsProcRunning = true; } - if (PlatformUtil.RunningOnLinux) + try { - string[] memoryInfo = await File.ReadAllLinesAsync("/proc/meminfo", cancellationToken); - if (cancellationToken.IsCancellationRequested) + if (PlatformUtil.RunningOnWindows) { - return; - } + await Task.Run(() => + { + using var query = new ManagementObjectSearcher("SELECT FreePhysicalMemory, TotalVisibleMemorySize FROM CIM_OperatingSystem"); - // The /proc/meminfo file contains several memory counters. To calculate the available memory - // we need to get the total memory and the available memory counters - // The available memory contains the sum of free, cached, and buffer memory - // it shows more accurate information about the memory usage than the free memory counter - int totalMemory = int.Parse(memoryInfo[0].Split(" ", StringSplitOptions.RemoveEmptyEntries)[1]); - int availableMemory = int.Parse(memoryInfo[2].Split(" ", StringSplitOptions.RemoveEmptyEntries)[1]); + ManagementObject memoryInfo = query.Get().OfType().FirstOrDefault() ?? throw new Exception("Failed to execute WMI query"); + var freeMemory = Convert.ToInt64(memoryInfo["FreePhysicalMemory"]); + var totalMemory = Convert.ToInt64(memoryInfo["TotalVisibleMemorySize"]); - lock (_memoryInfoLock) - { - _memoryInfo.Updated = DateTime.Now; - _memoryInfo.TotalMemoryMB = totalMemory / 1024; - _memoryInfo.UsedMemoryMB = (totalMemory - availableMemory) / 1024; + lock (_memoryInfoLock) + { + _memoryInfo.Updated = DateTime.Now; + _memoryInfo.TotalMemoryMB = totalMemory / 1024; + _memoryInfo.UsedMemoryMB = (totalMemory - freeMemory) / 1024; + } + }, cancellationToken); } - } - if (PlatformUtil.RunningOnMacOS) - { - lock (_memoryInfoLock) + if (PlatformUtil.RunningOnLinux) { - if (_memoryInfo.IsProcRunning) + string[] memoryInfo = await File.ReadAllLinesAsync("/proc/meminfo", cancellationToken); + if (cancellationToken.IsCancellationRequested) { return; } - _memoryInfo.IsProcRunning = true; + + // The /proc/meminfo file contains several memory counters. To calculate the available memory + // we need to get the total memory and the available memory counters + // The available memory contains the sum of free, cached, and buffer memory + // it shows more accurate information about the memory usage than the free memory counter + int totalMemory = int.Parse(memoryInfo[0].Split(" ", StringSplitOptions.RemoveEmptyEntries)[1]); + int availableMemory = int.Parse(memoryInfo[2].Split(" ", StringSplitOptions.RemoveEmptyEntries)[1]); + + lock (_memoryInfoLock) + { + _memoryInfo.Updated = DateTime.Now; + _memoryInfo.TotalMemoryMB = totalMemory / 1024; + _memoryInfo.UsedMemoryMB = (totalMemory - availableMemory) / 1024; + } } - try + if (PlatformUtil.RunningOnMacOS) { // vm_stat allows to get the most detailed information about memory usage on MacOS // but unfortunately it returns values in pages and has no built-in arguments for custom output @@ -367,14 +389,15 @@ await processInvoker.ExecuteAsync( _memoryInfo.UsedMemoryMB = usedMemory / 1048576; } } - finally + } + finally + { + lock (_memoryInfoLock) { - lock (_memoryInfoLock) - { - _memoryInfo.IsProcRunning = false; - } + _memoryInfo.IsProcRunning = false; } } + } #endregion From bed69b57dd2932c273794a2deb1191bf555d0f65 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Thu, 9 Jan 2025 11:10:58 +0530 Subject: [PATCH 50/51] formatting change --- src/Agent.Worker/ResourceMetricsManager.cs | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/Agent.Worker/ResourceMetricsManager.cs b/src/Agent.Worker/ResourceMetricsManager.cs index 40ef3a8241..632e53b523 100644 --- a/src/Agent.Worker/ResourceMetricsManager.cs +++ b/src/Agent.Worker/ResourceMetricsManager.cs @@ -238,7 +238,6 @@ await processInvoker.ExecuteAsync( _cpuInfo.IsProcRunning = false; } } - } private void GetDiskInfo() @@ -397,7 +396,6 @@ await processInvoker.ExecuteAsync( _memoryInfo.IsProcRunning = false; } } - } #endregion From c6e1003a1fa50bf2c1efc1be49678715c363eb19 Mon Sep 17 00:00:00 2001 From: Sahil Manoj Bhatt Date: Thu, 9 Jan 2025 14:03:16 +0530 Subject: [PATCH 51/51] steps runner set context --- src/Agent.Worker/StepsRunner.cs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/Agent.Worker/StepsRunner.cs b/src/Agent.Worker/StepsRunner.cs index 23b30cbc5d..b9bee6eb81 100644 --- a/src/Agent.Worker/StepsRunner.cs +++ b/src/Agent.Worker/StepsRunner.cs @@ -88,8 +88,8 @@ public async Task RunAsync(IExecutionContext jobContext, IList steps) } // Change the current job context to the step context. - // var resourceDiagnosticManager = HostContext.GetService(); - // resourceDiagnosticManager.SetContext(step.ExecutionContext); + var resourceDiagnosticManager = HostContext.GetService(); + resourceDiagnosticManager.SetContext(step.ExecutionContext); // Variable expansion. step.ExecutionContext.SetStepTarget(step.Target);