This is long. Bear with me, as I will really go through all the convoluted
stuff that shows there is a problem with streams (at least when used to
redirect stdout).
The basic idea is that my application (VB.NET) will start a process,
redirect its stdout and capture that process' output, displaying it in a
window.
I've written a component for this, and a test application for the component.
It allows me to specify a command to execute, and also whether that command
is executed via a cmd.exe shell (like "dir"), or not (such as when directly
running a console application).
I then found a nearly identical solution in an article at
http://www.codeguru.com/Csharp/Cshar...cle.php/c8503/
That article contains pretty much what I also have done.
So here's the problem. It appears that there is something weird about
console applications that can make them hang or not output when run in this
way (through System.Diagnost ics.Process).
Just to head off some questions, when I am reading my redirected stdout and
stderr, I always peek first, then read the character. Yes, char-at-a-time is
not terribly efficient, but it works for this purpose.
Note that to intercept stdout/stderr, you have to start the application with
no window (per docs on the Process object).
I have a particular console app that I'm capturing. This application, once
started, outputs lines as it progresses, and eventually completes. It takes
no user input -- it simply logs lines to stdout. Sounds simple.
Observations:
- Start cmd.exe and run this application; it works fine.
- My interceptor starts the application by starting cmd.exe (with no window)
and then having that process start the application by feeding its stdin with
the command line necessary to do so. In this case, it is cmd.exe which my
application is intercepting, and so I get whatever cmd.exe would output. I do
get the initial two lines introducing cmd.exe (with version and so forth),
and the prompt line, and I see the command to start the application after the
prompt. The application does start (as seen in task list), but no further
output is captured. Breakpoints verify that in fact nothing is being seen in
the stdout or stderr pipes at all. HOWEVER... this is only true when the
application is long-running (and so I eventually abort it). When I run it on
a very short test, which results in the application completing in a few
seconds, and producing only a few lines, then these lines ARE presented to
stdout and captured!
- The interceptor starts the application directly (not via cmd.exe). No
output is seen (but not attempted on the short-running case).
This all made me think that the output is buffered, and indeed it is
normally, per documentation of printf (and the target app is a C app). So I
decided I'd check this out by creating a very simple console app in VB.NET.
The simplest version is this one:
-----------------------
Sub Main()
Dim nLine As Integer
System.Console. WriteLine("RBAC console write test.")
For nLine = 1 To 20
System.Console. WriteLine(Strin g.Format("Conso le write test --
line {0}.", nLine))
Next
System.Console. WriteLine("Done .")
End Sub
------------------------------
When I run this directly (not via cmd.exe), my interceptor gets the outputs
expected:
--------------
RBAC console write test.
Console write test -- line 1.
Console write test -- line 2.
Console write test -- line 3.
Console write test -- line 4.
Console write test -- line 5.
Console write test -- line 6.
Console write test -- line 7.
Console write test -- line 8.
Console write test -- line 9.
Console write test -- line 10.
Console write test -- line 11.
Console write test -- line 12.
Console write test -- line 13.
Console write test -- line 14.
Console write test -- line 15.
Console write test -- line 16.
Console write test -- line 17.
Console write test -- line 18.
Console write test -- line 19.
Console write test -- line 20.
Done.
----------------
and when run via cmd.exe:
-----------------
Microsoft Windows XP [Version 5.1.2600]
(C) Copyright 1985-2001 Microsoft Corp.
C:\00sts\RBAC\N ET\ConsoleAppTe st\ConsoleAppTe st\bin>consoleA ppTest.exe
-----------------
That is, the output doesn't appear when the interceptor starts cmd.exe and
feeds the command to it. As you can see, the command itself is fine. To
verify that commands can be intercepted, I execute "dir" in the same context,
via the interceptor:
--------------------
Microsoft Windows XP [Version 5.1.2600]
(C) Copyright 1985-2001 Microsoft Corp.
C:\00sts\RBAC\N ET\ConsoleAppTe st\ConsoleAppTe st\bin>dir
Volume in drive C has no label.
Volume Serial Number is E8B4-4400
Directory of C:\00sts\RBAC\N ET\ConsoleAppTe st\ConsoleAppTe st\bin
07/21/2005 06:46 PM <DIR> .
07/21/2005 06:46 PM <DIR> ..
07/22/2005 12:34 PM 6,656 ConsoleAppTest. exe
07/22/2005 12:34 PM 11,776 ConsoleAppTest. pdb
2 File(s) 18,432 bytes
2 Dir(s) 9,501,356,032 bytes free
C:\00sts\RBAC\N ET\ConsoleAppTe st\ConsoleAppTe st\bin>exit
------------------------
This shows that in fact I should get whatever is displayed in the console.
So I then start up cmd.exe manually, and run the ConsoleAppTest. exe:
---------------------
C:\00sts\RBAC\N ET\ConsoleAppTe st\ConsoleAppTe st\bin>consolea pptest
RBAC console write test.
Console write test -- line 1.
Console write test -- line 2.
Console write test -- line 3.
Console write test -- line 4.
Console write test -- line 5.
Console write test -- line 6.
Console write test -- line 7.
Console write test -- line 8.
Console write test -- line 9.
Console write test -- line 10.
Console write test -- line 11.
Console write test -- line 12.
Console write test -- line 13.
Console write test -- line 14.
Console write test -- line 15.
Console write test -- line 16.
Console write test -- line 17.
Console write test -- line 18.
Console write test -- line 19.
Console write test -- line 20.
Done.
------------------------------
This just shows that normally in cmd.exe, I will get the output.
While most of this is background for what comes next, there is already the
inexplicable failure to find the lines of output when cmd.exe is started
through the Process class.
Below is the code for starting the process, whether using cmd.exe or not.
Not that "swOut" and "swErr" are StreamReader objects declared at the object
scope of the encapsulating class.
------------------
Dim swIn As StreamWriter
oProc = New Process
If bUseCmdExe Then
oProc.StartInfo .FileName = "cmd.exe"
Else
oProc.StartInfo .FileName = sRunningCommand
End If
oProc.StartInfo .UseShellExecut e = False ' can't use shell
execute when we will be redirecting output.
oProc.StartInfo .ErrorDialog = False
oProc.StartInfo .CreateNoWindow = True
oProc.StartInfo .RedirectStanda rdError = True
oProc.StartInfo .RedirectStanda rdInput = bUseCmdExe
oProc.StartInfo .RedirectStanda rdOutput = True
If sWorkingDir <> "" Then
oProc.StartInfo .WorkingDirecto ry =
Path.GetFullPat h(sWorkingDir)
If Not bUseCmdExe Then
' set the default path
ChDir(Path.GetF ullPath(sWorkin gDir))
oProc.StartInfo .FileName = Path.GetFullPat h(sWorkingDir)
& sRunningCommand
End If
End If
oProc.Start()
If bUseCmdExe Then
swin = oProc.StandardI nput
swIn.AutoFlush = True
End If
swOut = oProc.StandardO utput
swErr = oProc.StandardE rror
If bUseCmdExe Then
' The idea is to start a hidden command process, and feed it
the string to be executed
' via the redirected stdin.
swIn.WriteLine( sRunningCommand )
swIn.WriteLine( "exit") ' after running, exit the invisible
command process.
End If
-------------------
Note: I have tried indicating that the output and err StreamReaders are
synchronized, as this creation code happens in a new thread which is also
used to monitor the readers. This did not have any effect on results.
Now, we already have one weird result (the output from the test app not
appearing when cmd.exe is used to run it from the interceptor). We are about
to get REALLY weird.
Recall that when NOT using cmd.exe, but running the console test app
directly via the interceptor, all expected lines were captured. Now let's
change the console app:
----------------
Sub Main()
Dim nLine As Integer
System.Console. WriteLine("RBAC console write test.")
For nLine = 1 To 20
System.Console. WriteLine(Strin g.Format("Conso le write test --
line {0}.", nLine))
Threading.Threa d.Sleep(100)
Next
System.Console. WriteLine("Done .")
End Sub
-------------------
The only change is the addition of Thread.Sleep after the first line. I then
ran this version by starting cmd.exe manually and got all expected lines.
But... now I'm going to run this in the interceptor, using the exact same
mode that worked before putting in the sleep. We capture:
------------------
RBAC console write test.
Console write test -- line 1.
------------------
That's right -- no line after the Sleep is captured. Even though the app
runs, and works fine in a manual cmd.exe, and even though nothing changed
other than the 100 ms sleep between lines, the redirected stdout no longer
gets any further characters on the output end of the pipe.
At this point I've tried many variations, including having my console test
app use a timer instead of sleep, doing various things with threading and so
forth, but anything that might result in any suspension of the line-writing
loop appears to have this effect on the output pipe, which is that nothing
comes out the other end.
This is a serious problem in that something this simple clearly should not
break the pipe. Remember, just writing the 20 lines to the output pipe
results in all 20 lines appearing at the other end of the pipe, but adding a
Sleep between the lines immediately halts output at the pipe. Whether or not
anything is actually being sent is unclear, but the application does
terminate normally in either case.
There's more -- I can really get this process messed up. First, let's take
the string we write and make it long -- by adding about 400 characters. Take
out the sleep:
--------------------
Sub Main()
Dim nLine As Integer
System.Console. WriteLine("RBAC console write test.")
For nLine = 1 To 20
System.Console. WriteLine(Strin g.Format("12345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 67890Console
write test -- line {0}.", nLine))
Next
System.Console. WriteLine("Done .")
End Sub
---------------------
Run it in a command window and you get the expected output. Run it with the
interceptor, not via cmd.exe and get:
---------------
RBAC console write test.
123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 1234567890Conso le write test -- line 1.
123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 1234567890Conso le write test -- line 2.
123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 1234567890Conso le write test -- line 3.
123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 1234567890Conso le write test -- line 4.
123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 1234567890Conso le write test -- line 5.
123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 1234567890Conso le write test -- line 6.
123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 1234567890Conso le write test -- line 7.
123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 1234567890Conso le write test -- line 8.
123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 1234567890Conso le write test -- line 9.
123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 1234567890Conso le write test -- line 10.
123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 1234567890Conso le write test -- line 11.
123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 1234567890Conso le write test -- line 12.
123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 1234567890Conso le write test -- line 13.
123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 1234567890Conso le write test -- line 14.
123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 1234567890Conso le write test -- line 15.
123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 1234567890Conso le write test -- line 16.
123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 1234567890Conso le write test -- line 17.
123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 1234567890Conso le write test -- line 18.
123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 1234567890Conso le write test -- line 19.
123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 1234567890Conso le write test -- line 20.
Done.
-------------------------------
So this again is as expected, without the sleep on it. Put the sleep back
and as before we get just the first line (before the first Sleep):
----------------------------
RBAC console write test.
123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 1234567890Conso le write test -- line 1.
------------------------------
Ok - so what? Just as expected, right? Well, yes... except for the fact that
now, with the longer message, ConsoleAppTest actually doesn't even
terminate... it just stays in the task list! Before this, it always
terminated, but when this pipe problem occurs and "enough" is written to the
pipe, apparently the application hangs.
Next I changed the message, adding another 800 characters to the message.
Interestingly, I now get the first two messages! That is, I get the one just
before and just after the sleep, but no others:
--------------
RBAC console write test.
123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 Console write test -- line 1.
123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 Console write test -- line 2.
---------------------------------------
The application still, however, hangs and does not terminate. Apparently,
something is triggering the pipe to flush, but not consistently. By this time
you probably have started guessing I should just flush the stream.
----------------
Sub Main()
Dim nLine As Integer
System.Console. WriteLine("RBAC console write test.")
For nLine = 1 To 20
System.Console. WriteLine(Strin g.Format("12345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 123456789012345 678901234567890 1234567890
Console write test -- line {0}.", nLine))
'System.Console .Out.Flush()
Threading.Threa d.Sleep(100)
Next
System.Console. WriteLine("Done .")
End Sub
-------------------------
But this gives no change at all. Still getting the first 2 lines, then the
app doesn't terminate. Interestingly, I can change the sleep to 1000 and
watch the memory usage in task manager go up as the application writes to the
stream's buffer.
So that's it -- with Sleep, or anything might suspend, sleep, change
threads, etc. -- the pipe is broken. And remember, this is just a simple test
app. The actual application to be monitored is far more complex, but seems to
give the same result.
Why does the other end of the pipe work intermittently, and what can be done
to fix this?
I do have some support calls to use, and probably will need to, but this
message can serve to explain the problem.
