An experiment with redirected output and error streams to check the order in which strings emerge at the monitoring process. category 'experiment', language C#, created 31-Mar-2010, version V1.0, by Luc Pattyn |
License: The author hereby grants you a worldwide, non-exclusive license to use and redistribute the files and the source code in the article in any way you see fit, provided you keep the copyright notice in place; when code modifications are applied, the notice must reflect that. The author retains copyright to the article, you may not republish or otherwise make available the article, in whole or in part, without the prior written consent of the author. Disclaimer: This work is provided “as is”, without any express or implied warranties or conditions or guarantees. You, the user, assume all risk in its use. In no event will the author be liable to you on any legal theory for any special, incidental, consequential, punitive or exemplary damages arising out of this license or the use of the work or otherwise. |
This article describes an experiment where the output
and error
streams of a slave
process are monitored by a master process.
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:
O
sends a little string to the output stream;E
sends a little string to the error stream;1
causes a delay of one second;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.
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);
}
}
}
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 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:
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.
Perceler |
Copyright © 2012, Luc Pattyn |
Last Modified 02-Sep-2013 |