What is breaking my Process.StartInfo.OutputDataReceived callbacks prematurely?

Question

The following problem occurs on .NET Framework v3.5. Don't know if it applies to v4*.

To capture stdout for some processes I've successfully used p.StartInfo.UseShellExecute = false; and p.StartInfo.RedirectStandardOutput = true; and an event handler hooked to p.StartInfo.OutputDataReceived+=...;. Then I call p.Start(); then p.BeginOutputReadLine(); and then p.WaitForExit();

All is well so far. I get all stdout on the event handler, line by line, as expected.

I had to introduce a timeout instead of WaitForExit() because some processes unpredictably trigger requests for input at stdin (e.g. are you sure? [y/n]) leading to a deadlock where I wait forever and so do they.

The first thing I tried is changing to while (!p.HasExited && DateTime.Now < timeoutmom) p.WaitForExit(200); where timeoutmoment is 2 minutes after proc.Start(). This is when I ran into problems. Very consistently, the code works for calls that produce up to a few hundred lines of stdout but it breaks for one call that produces about 7500 lines. What happens is the proc.WaitForExit(200); thread exits the while when my OutputDataReceived event handler was called for only ~ 7300 lines (this number is again very consistent it varies by only +/- 1 between tests) and the handler is not called anymore for the rest of the stdout lines so I lose them.

Strangely, the problem doesn't appear if I avoid WaitForExit(200) and instead use while (!p.HasExited && DateTime.Now < timeoutmom) System.Threading.Thread.Sleep(1000); (not shown in the code below). When I posted the question I was pretty sure the problem was avoided using Sleep(1000) but I was wrong. It worked a few dozen times like that and then it didn't, it started behaving just like when I checked WaitForExit(200).

I now speculate that the reasons for this problem are (1) I take too long to process each OutputDataReceived callback. I noticed the problem was aggravated when I added a conditional breakpoint in the event handler which lengthened the method execution by a lot. I can now reproduce the problem by simply adding 3x Debug.WriteLines without the conditional breakpoint; PLUS (2) my context is somehow corrupted by me accessing HasExited / WaitForExit(200) before the system had a chance to perform all the callbacks on my event handler. I now do a blind System.Threading.Thread.Sleep(30000) just after p.Start() and before accessing any p.* method and I get all the callbacks. When I used WaitForExit() it seemed I can take however much time I want to process every callback and I would still get them all.

Can someone make more sense of this?

Code:

    private int _execOsProc(
        ProcessStartInfo Psi
        , string SecInsensArgs
        , TextWriter ExtraStdOutAndErrTgt
        , bool OutputToExtraStdOutOnly
        )
    {
        var pr = new Process();
        pr.StartInfo = Psi;
        pr.StartInfo.UseShellExecute = false;
        pr.StartInfo.RedirectStandardOutput = pr.StartInfo.RedirectStandardError = true;
        pr.StartInfo.CreateNoWindow = true;
        var ol = new DataReceivedEventHandler(this._stdOutDataReceived);
        var el = new DataReceivedEventHandler(this._stdErrDataReceived);
        pr.OutputDataReceived += ol;
        pr.ErrorDataReceived += el;
        try
        {
            __logger.Debug("Executing: \"" + pr.StartInfo.FileName + "\" " + SecInsensArgs);
            if (ExtraStdOutAndErrTgt == null)
            {
                this.__outputToExtraStdOutOnly = false;
            }
            else
            {
                this.__extraStdOutAndErrTgt = ExtraStdOutAndErrTgt;
                this.__outputToExtraStdOutOnly = OutputToExtraStdOutOnly;
            }
            pr.Start();
            pr.BeginOutputReadLine();
            pr.BeginErrorReadLine();
            var startmom = DateTime.Now;
            var timeoutmom = startmom.AddMinutes(2);
            while (!pr.HasExited && DateTime.Now < timeoutmom) pr.WaitForExit(200);
            pr.CancelOutputRead();
            pr.CancelErrorRead();
            if (pr.HasExited)
            {
                __logger.Debug("Execution finished with exit status code: " + pr.ExitCode);
                return pr.ExitCode;
            }
            else
            {
                __logger.Debug("Timeout while waiting for execution to finish");
                pr.Kill();
                return -100;
            }
        }
        finally
        {
            pr.OutputDataReceived -= ol;
            pr.ErrorDataReceived -= el;
            if (this.__extraStdOutAndErrTgt != null)
            {
                this.__extraStdOutAndErrTgt = null;
                this.__outputToExtraStdOutOnly = false;
            }
        }
    }

    private void _stdOutDataReceived(
        object sender
        , DataReceivedEventArgs e
        )
    {
        string rdata = string.IsNullOrEmpty(e.Data) ? "" : e.Data.Trim();
        if (!this.__outputToExtraStdOutOnly) __logger.Debug("SO: " + rdata);
        if (this.__extraStdOutAndErrTgt != null)
        {
            lock (this.__extraStdOutAndErrTgt)
            {
                try
                {
                    this.__extraStdOutAndErrTgt.WriteLine(rdata);
                    this.__extraStdOutAndErrTgt.Flush();
                }
                catch (Exception exc)
                {
                    __logger.Warn(
                                "WARNING: Error detected but ignored during extra stream write"
                                    + " on SODR. Details: " + exc.Message
                                , exc
                                );
                }
            }
        }
    }

    private void _stdErrDataReceived(
        object sender
        , DataReceivedEventArgs e
        )
    {
        string rdata = string.IsNullOrEmpty(e.Data) ? "" : e.Data.Trim();
        if (!__outputToExtraStdOutOnly) __logger.Debug("SE: " + rdata);
        if (this.__extraStdOutAndErrTgt != null)
        {
            lock (this.__extraStdOutAndErrTgt)
            {
                try
                {
                    this.__extraStdOutAndErrTgt.WriteLine(rdata);
                    this.__extraStdOutAndErrTgt.Flush();
                }
                catch (Exception exc)
                {
                    __logger.Warn(
                                "WARNING: Error detected but ignored during extra stream write"
                                    + " on SEDR. Details: " + exc.Message
                                , exc
                                );
                }
            }
        }
    }

Answer 1

I'm not sure if it will solve the problem, but it is too long to post it in the comment.

MSDN says about Process.HasExited:

When standard output has been redirected to asynchronous event handlers, it is possible that output processing will not have completed when this property returns true. To ensure that asynchronous event handling has been completed, call the WaitForExit() overload that takes no parameter before checking HasExited.

and about WaitForExit():

This overload ensures that all processing has been completed, including the handling of asynchronous events for redirected standard output. You should use this overload after a call to the WaitForExit(Int32) overload when standard output has been redirected to asynchronous event handlers.

It indicates, that call to WaitForExit() with no parameters should solve the problem. Something like:

var startmom = DateTime.Now;
var timeoutmom = startmom.AddMinutes(2);
while (!pr.HasExited && DateTime.Now < timeoutmom)
    pr.WaitForExit(200);

if (pr.HasExited)
{
    WaitForExit();//Ensure that redirected output buffers are flushed

    pr.CancelOutputRead();
    pr.CancelErrorRead();

    __logger.Debug("Execution finished with exit status code: " + pr.ExitCode);
    return pr.ExitCode;
}
else
{
    pr.CancelOutputRead();
    pr.CancelErrorRead();

    __logger.Debug("Timeout while waiting for execution to finish");

    pr.Kill();
    return -100;
}