The Process Async Reader Bug

The Problem

Let's say that you launch the same process twice from two different threads, like this:

using System;
using System.IO;
using System.Threading;

using Clifton.Timers;

namespace Launcher
{
  class Program
  {
    enum Process
    {
      Proc1, 
      Proc2,
    }

    static void Main(string[] args)
    {
      Thread t1 = new Thread(new ThreadStart(Launch1));
      Thread t2 = new Thread(new ThreadStart(Launch2));
      t1.Start();
      t2.Start();
      t1.Join();
      t2.Join();
    }

    static void Launch1()
    {
      DebugStopwatch.Start(Process.Proc1);
      LaunchAndWait(5000, "P1");
      DebugStopwatch.Stop(Process.Proc1);
      long t = 0;
      DebugStopwatch.ElapsedMilliseconds(Process.Proc1, ref t);
      Console.WriteLine("P1 took " + t + " ms");
    }

    static void Launch2()
    {
      DebugStopwatch.Start(Process.Proc2);
      LaunchAndWait(10000, "P2");
      DebugStopwatch.Stop(Process.Proc2);
      long t = 0;
      DebugStopwatch.ElapsedMilliseconds(Process.Proc2, ref t);
      Console.WriteLine("P2 took " + t + " ms");
    }

    static void LaunchAndWait(int ms, string procName)
    {
      Executable exec = new Executable(Path.GetFullPath(
         "..\\..\\..\\TestProcess\\bin\\debug\\TestProcess.exe"), ms.ToString());
      exec.Start();
      exec.WaitForExitInfinite();
      Console.WriteLine(procName + " done.");
    }
  }
}

The LaunchAndWait method calls WaitForExitInfinite, which is this:

public void WaitForExitInfinite()
{
  exe.WaitForExit();
}

where exe is an instance of the .NET Process class.

The process does nothing more than sleep for the amount of time specified in the command line arguments:

using System;
using System.Threading;

namespace TestProcess
{
  class Program
  {
    static void Main(string[] args)
    {
      Thread.Sleep(Convert.ToInt32(args[0]));
    }
  }
}

So, since Launch1 passes in 5000 and Launch2 passes in 10000, you would expect (correctly) that the result from the timers are:

P1 done.
P1 took 5091 ms
P2 done.
P2 took 10094 ms
Press any key to continue . . .

The class Executable, in this case, does nothing more than launch the process. Note the commented calls to begin the async output and error readers:

public void Start()
{
  exe = new Process();
  exe.StartInfo.FileName = filename;
  exe.StartInfo.UseShellExecute = false;
  exe.StartInfo.RedirectStandardInput = true;
  exe.StartInfo.RedirectStandardOutput = true;
  exe.StartInfo.RedirectStandardError = true;
  exe.StartInfo.CreateNoWindow = false;
  exe.StartInfo.Arguments = arguments;
  exe.ErrorDataReceived += new DataReceivedEventHandler(MonitorError);
  exe.OutputDataReceived += new DataReceivedEventHandler(MonitorOutput);
  exe.Start();
//exe.BeginOutputReadLine();
//exe.BeginErrorReadLine();
}

Now, watch--I'll uncomment the two lines above and rerun the test, the result of which is:

P1 done.
P2 done.
P1 took 10061 ms
P2 took 10061 ms
Press any key to continue . . .

So, simply by enabling async reading, the first process does not indicate that it is terminated until the second process terminates!

The Solution

The solution is to call Process.WaitForExit with a timeout, say 100ms. So, I change the LaunchAndWait to call WaitForExit instead of WaitForExitInfinite:

static void LaunchAndWait(int ms, string procName)
{
  Executable exec = new Executable(Path.GetFullPath(
       "..\\..\\..\\TestProcess\\bin\\debug\\TestProcess.exe"), ms.ToString());
  exec.Start();
  exec.WaitForExit();
  Console.WriteLine(procName + " done.");
}

Compare the WaitForExit call with the above WaitForExitInfinite call:

public void WaitForExit()
{
  bool running = true;

  while (running)
  {
    running = !exe.WaitForExit(100); 
  }
}

This call, while waiting forever as well, passes in a timeout value to Process.WaitForExit, and relies on the return code to test whether the process has terminated. With this call, the first process exits after 5 seconds and the second process after 10 seconds, as we would have expected.

Conclusion

I didn't discover this bug until I was testing a multithreaded movie re-encoder and the code wouldn't assign a new job to the first completed process until the second process had completed. Always suspecting my code first, I was dismayed to discover that this problem was with the async reader, which is vital in getting feedback from the re-encoder process. I had searched for other people that had encountered this problem but my search came up blank, so I ended up writing this article. If anyone has any further information about this problem, post a comment!