Skip to content

Commit

Permalink
Another round of improvements for ProcessRunner
Browse files Browse the repository at this point in the history 
More stabs in the dark.

The changes in 72cc826 did not have any affect on the timeouts, however the processes that time out DO now capture their standard out and error. This means that even though processes are timing out, they are tantilizingly close to actually working.

This change gives the process runner a chance to return as if it were sucessful, despite timing out.

We also improve the logging so we can track the effects on the concurrency better.
  • Loading branch information
@atruskie
atruskie committed Apr 27, 2018
1 parent bc45344 commit 75bc53b
Showing 1 changed file with 43 additions and 7 deletions.
50 changes: 43 additions & 7 deletions src/Acoustics.Shared/ProcessRunner.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,7 @@ namespace Acoustics.Shared
using System.Diagnostics;
using System.IO;
using System.Linq;
using System.Runtime.Serialization;
using System.Text;
using System.Threading.Tasks;
using Fasterflect;
Expand All @@ -21,13 +22,15 @@ namespace Acoustics.Shared
public class ProcessRunner : IDisposable
{
private static readonly ILog Log = LogManager.GetLogger(nameof(ProcessRunner));
private static readonly ObjectIDGenerator InstanceTracker = new ObjectIDGenerator();

private StringBuilder standardOutput;
private StringBuilder errorOutput;
private List<string> failedRuns;
private Process process;
private bool exitCodeSet;
private int exitCode;
private long instanceId;

/// <summary>
/// Initializes a new instance of the <see cref="ProcessRunner"/> class.
Expand All @@ -54,6 +57,10 @@ public ProcessRunner(string filePath)

this.WaitForExit = true;
this.MaxRetries = 0;
lock (this)
{
this.instanceId = InstanceTracker.GetId(this, out var _);
}
}

public int ExitCode
Expand Down Expand Up @@ -235,6 +242,11 @@ private void PrepareRun(string arguments, string workingDirectory)

this.Dispose();

if (Log.IsVerboseEnabled())
{
Log.Verbose(this.instanceId + ": Process runner arguments:" + arguments);
}

this.process = new Process
{
StartInfo = new ProcessStartInfo
Expand Down Expand Up @@ -287,7 +299,7 @@ private void KillProcess()
// success, quit
if (Log.IsVerboseEnabled())
{
Log.Verbose("Process killed after" + exceptions.Count + " handling code");
Log.Verbose(this.instanceId + ": Process killed after " + exceptions.Count + " attempts. Exit code: " + this.exitCode);
}

return;
Expand Down Expand Up @@ -338,6 +350,11 @@ private void RunAndRead(string arguments, string workingDirectory, int retriedCo

if (this.WaitForExitMilliseconds > 0)
{
// there are varoius bugs with the MONO implementation of this. here are two that are relevant:
// https://bugzilla.xamarin.com/show_bug.cgi?id=27246
// https://github.com/mono/mono/issues/6200
// The upshot on this is that sometimes SIGCHLD will not be captured by mono, resulting in a
// garunteed timeout in high concurrency scenarios
var exited = this.process.WaitForExit(this.WaitForExitMilliseconds);

// https://msdn.microsoft.com/en-us/library/ty0d8k56(v=vs.110).aspx
Expand All @@ -347,6 +364,11 @@ private void RunAndRead(string arguments, string workingDirectory, int retriedCo
// overload that takes no parameter after receiving a true from this overload.
if (exited)
{
if (Log.IsVerboseEnabled())
{
Log.Verbose(this.instanceId + ": Process exited without timing out: " + this.process.ExitCode);
}

this.process.WaitForExit();
}
else
Expand All @@ -363,10 +385,6 @@ private void RunAndRead(string arguments, string workingDirectory, int retriedCo
}

this.ExitCode = this.process.ExitCode;
if (Log.IsVerboseEnabled())
{
Log.Verbose("Process exited without timing out: " + this.process.ExitCode);
}
}

void OnProcessOnErrorDataReceived(object sender, DataReceivedEventArgs e)
Expand All @@ -390,7 +408,7 @@ private void ProcessTimeout(string arguments, string workingDirectory, int retry
{
if (Log.IsVerboseEnabled())
{
Log.Verbose("Process timeout handling code");
Log.Verbose(this.instanceId + ": Process timeout handling code. Exit code: " + this.process.ExitCode);
}

this.process.Refresh();
Expand All @@ -401,6 +419,24 @@ private void ProcessTimeout(string arguments, string workingDirectory, int retry
this.KillProcess();
}

// wild guess code - we're unable to really test this code except in high concurrency scenarios
// So timeouts are common in high concurrency scenarios because SIGCHLD are sometimes not captured by mono.
// The process is theoretically completing sucessfully but mono doesn't notice (see note in RunAndRead).
// If (despite timing out) however the exit code was captured, and execution was sucessfull, and we
// captured output, then there's a really nothing wrong with the execution (other than it timed out unnecessarilly).
// The following code cpatures the spirit of this notion and allows us to not repeat another failed timeout run if
// execution was probably successful.
if (this.process.ExitCode == 0 && (this.StandardOutput.Length > 0 || this.ErrorOutput.Length > 0))
{
// execution probably successful... continue as if it had worked
if (Log.IsVerboseEnabled())
{
Log.Verbose(this.instanceId + ": Process timeout handling code. Continuing without retrying, execution was ***probably*** successful! Exit code: " + this.process.ExitCode);
}

return;
}

this.failedRuns.Add(string.Format(
"[{0} UTC] {1} with args {2} running in {3}. Waited for {4:c}. Process had{5} already terminated after timeout.\n\nStdout: {6}\n\nStderr: {7}",
DateTime.UtcNow.ToString("s", System.Globalization.CultureInfo.InvariantCulture),
Expand All @@ -416,7 +452,7 @@ private void ProcessTimeout(string arguments, string workingDirectory, int retry
{
if (Log.IsVerboseEnabled())
{
Log.Verbose("Process run retying");
Log.Verbose(this.instanceId + ": Process run retying");
}

retryMethod(arguments, workingDirectory, retryCount + 1);
Expand Down

0 comments on commit 75bc53b

Please sign in to comment.