Article: An experiment with Process streams (output and error)

This article describes an experiment where the output and error streams of a slave process are monitored by a master process.

The experiment

We want to see in what order different outputs from one process will be received by another program when using both output and error streams.

The slave process is a windowless application that takes a command line argument, which consists of individual characters, each causing a simple action:

• an O sends a little string to the output stream;
• an E sends a little string to the error stream;
• a 1 causes a delay of one second;
• an A causes a delay of one second being added on all consequent 'O' and 'E' commands.

The strings generated by the slave process start with the relevant letter ('O', 'E', 'A') followed by the sequence number, which is the 1-based index in the command string. And they end on the time they were created.

The master process is a Windows Application, offering a TextBox holding the command line for the slave process, a "Start" button, and a ListBox logging all relevant events. When the button gets clicked, the slave process is launched with the intended command line, its output and error streams are redirected and logged in the ListBox, which prefixes the receiving time to each line.

The code of the slave process

using System;
using System.Threading;

namespace SlaveProcess {
	static class SlaveProcess {
		[STAThread]
		static void Main() {
			bool autowait=false;
			string[] args=Environment.GetCommandLineArgs();
			if (args.Length!=2) {
				Out("Expecting one command line argument, a string, where each char causes one action:");
				Out("O=output a line, E=Output an error line, 1=wait 1 second, A=always wait 1 second");
			} else {
				string commands=args[1];
				Out("commands="+commands);
				int charcount=0;
				foreach(char c in commands) {
					charcount++;
					string time=DateTime.Now.ToString("HH:mm:ss.fff ");
					switch (c) {
						case 'A':
							Out("A"+charcount.ToString("00")+": "+time);
							autowait=true;
							break;
						case '1':
							Thread.Sleep(1000);
							break;
						case 'O':
							System.Console.Out.WriteLine("O"+charcount.ToString("00")+": "+time);
							if (autowait) Thread.Sleep(1000);
							break;
						case 'E':
							System.Console.Error.WriteLine("E"+charcount.ToString("00")+": "+time);
							if (autowait) Thread.Sleep(1000);
							break;
						default:
							Out("Bad command: "+c);
							break;
					}
				}
				Out("Done");
			}
		}

		// while intended for logging (it logs to the Console when running within Visual Studio),
		// this method will send the message to the standard output stream, hence it may get
		// redirected by the master process.
		private static void Out(string s) {
			Console.WriteLine(s);
		}
	}
}

Some code of the master process

Here is the most important part of the master code.

// log one line of text in the ListBox (taking care of thread crossing)
private void log(string s) {
	if (lb.InvokeRequired) {
		lb.Invoke(new Action<string>(log), s);
	} else {
		if (s.Length!=0) s=DateTime.Now.ToString("HH:mm:ss.fff  ")+s;
		lb.Items.Add(s);
		lb.TopIndex=lb.Items.Count-1;
	}
}

private void btnStart_Click(object sender, EventArgs e) {
	log("");
	log("start");
	process=new Process();
	process.EnableRaisingEvents=true;
	process.Exited+=new EventHandler(process_Exited);
	process.StartInfo.FileName="SlaveProcess.exe";
	process.StartInfo.Arguments=tbCommand.Text;
	process.StartInfo.UseShellExecute=false;
	process.StartInfo.RedirectStandardOutput=true;
	process.StartInfo.RedirectStandardError=true;
	process.Start();
	process.ErrorDataReceived+=new DataReceivedEventHandler(process_ErrorDataReceived);
	process.OutputDataReceived+=new DataReceivedEventHandler(process_OutputDataReceived);
	process.BeginOutputReadLine();
	process.BeginErrorReadLine();
	log("launched");
}

void process_Exited(object sender, EventArgs e) {
	log("exited");
}

void process_OutputDataReceived(object sender, DataReceivedEventArgs e) {
	string s=e.Data;
	log("OutputDataReceived: "+s);
}

void process_ErrorDataReceived(object sender, DataReceivedEventArgs e) {
	string s=e.Data;
	log("ErrorDataReceived:  "+s);
}

The entire Visual Studio 2008 project is available here.

The actual tests

The main test consisted of the command OOOEOOOEOOOEOAOOEOOOEO which means first some output and error messages are interleaved without delay, then some more are interleaved with a 1-second delay.

We can observe:

1. that all output becomes available to the master well before the slave exits;
2. that all strings within a single stream (output or error) keep their order;
3. that strings from different streams don't keep their order, unless there is an explicit delay.

Conclusion

All strings from output and error streams become available while the slave process runs, they may or may not get a slightly different order, depending on some delays, which isn't a real surprise as there must be some buffering and thread switching going on, interfering with the exact timing of both streams.

History

• Version 1.0 (31-Mar-2010): Original version