I just closed a case that I thought was a bit interesting. I could skip directly to the old Problem, Resolution format, but I think that most of the time there is a lot to be learned from the troubleshooting process as well, so I'll simply describe the scenario as well as what I did to resolve it.

The tools I used for troubleshooting are Visual Studio 2005 and windbg.

Scenario:

The customer had a web application that was using ProcessStartInfo in Visual Studio 2005 to automate Robocopy.exe. He wanted to copy large directories back and forth between servers. I don't know the number of concurrent clients for this application, but I'm guessing it was <=1. Anyway the problem wasn't multiple users, it was the fact that when he tried to copy a large directory tree the application would hang. Robocopy would still be running but the main application was completely unresponsive.

In case you're experiencing something similar yourself and are eager to find out what the actual problem was I'll tell you straight away: The standard output buffer was full. It can hold a maximum of 4k. Robocopy was waiting for the standard output buffer to be flushed, and the web application was waiting for Robocopy.

Initial testing:

So the first tests were standard stuff, figuring out if this was due to a problem with the Robocopy application or not and to provide the customer with an acceptable alternative while troubleshooting. The customer had already found that if he turned on the "/LOG"-switch he was able to copy without problems. The "/LOG"-switch simply writes output to file rather than standard output, so this was something the customer could consider using if time was of the essence.

Setting up a repro:

Since we now suspected that we somehow hit a limit in standard output it was important to find out if this problem lied within Robocopy or if any console application with massive output would cause the same problem.

I created a simple console application that accepted a single argument X and used it to dump X * 100 character lines into standard output:

Module WriteALot
   Sub Main()
      If My.Application.CommandLineArgs.Count = 0 Then
         Console.WriteLine("You need to specify an integer")
         End
      ElseIf Not IsNumeric(My.Application.CommandLineArgs(0)) Then
         Console.WriteLine("You need to specify an integer")
         End
      End If
      Dim I As Integer
      For I = 1 To CInt(WriteALot.My.Application.CommandLineArgs(0))
         Console.WriteLine((I).ToString & " AAA BBB CCC DDD EEE FFF GGG HHH III JJJ KKK LLL MMM NNN OOO PPP QQQ RRR SSS TTT UUU VVV XXX YYY ZZZ")
      Next
   End Sub
End Module

I then created a simple winforms application that created an instance of this console application using ProcessStartInfo. I put a NumericUpDown-control, a button and a multi-line textbox on it. Creating a GUI that looks like this:

Finally I added the following code:

Public Class Form1
   Private Function WriteALot(ByVal iLines As Integer) As String
      Dim Output As String
      Dim pSI As New Diagnostics.ProcessStartInfo(".\WriteALot.exe", iLines.ToString)
      With pSI
         .UseShellExecute = False
         .RedirectStandardError = True
         .RedirectStandardOutput = True
         .CreateNoWindow = True
         .LoadUserProfile = False
      End With
      Dim srOutput, srErr As IO.StreamReader
      Dim p As New System.Diagnostics.Process
      p.StartInfo = pSI
      Try
         p.Start()
         srOutput = p.StandardOutput
         srErr = p.StandardError
         'Loop the thread until the process has completed
         While Not p.HasExited
            System.Threading.Thread.Sleep(10)
            If Not p.Responding Then p.Kill()
         End While
         Output = srOutput.ReadToEnd
         srOutput.Dispose()
         srErr.Dispose()
         Catch ex As Exception
         Output = "Error: " & ex.Message
      Finally
         pSI = Nothing
         p.Dispose()
      End Try
      Return Output
   End Function

   Private Sub btnWrite_Click(ByVal sender As System.Object, ByVal e As System.EventArgs) Handles btnWrite.Click
      txtStdOut.Text = "Writing " & NumericUpDown1.Value & " lines." & vbCrLf
      txtStdOut.Text += WriteALot(NumericUpDown1.Value) & vbCrLf
      txtStdOut.Text += "Complete"
   End Sub
End Class

My test application worked fine with anything up to 39 lines. After that it would hang.

Debugging

Since I didn't know at the time that there is a size limit for the standard output buffer I thought I'd take a look at what the two applications were doing using windbg and SOS. I reproduced the error and attached to the two processes. This is what the console application, WriteALot.exe, was doing:

0:003> !threads
ThreadCount: 2
UnstartedThread: 0
BackgroundThread: 1
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
PreEmptive GC Alloc Lock
ID OSID ThreadOBJ State GC Context Domain Count APT Exception
0 1 1db4 0078a300 6020 Enabled 028e0c58:028e1fe8 007864f8 1 STA
2 2 1cf8 00799ac0 b220 Enabled 00000000:00000000 007864f8 0 MTA (Finalizer)

0:001> ~0s
eax=00000000 ebx=00000021 ecx=00000000 edx=00000000 esi=ffffffff edi=00000000
eip=7735a6fd esp=0035f218 ebp=0035f280 iopl=0 nv up ei pl nz na po nc
cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000202
ntdll!NtWriteFile+0x15:
7735a6fd c22400 ret 24h

0:000> !clrstack
OS Thread Id: 0x1db4 (0)
ESP EIP
0035f2d0 7735a6fd [NDirectMethodFrameStandaloneCleanup: 0035f2d0] System.IO.__ConsoleStream.WriteFile(Microsoft.Win32.SafeHandles.SafeFileHandle, Byte*, Int32, Int32 ByRef, IntPtr)
0035f2ec 79377c34 System.IO.__ConsoleStream.WriteFileNative(Microsoft.Win32.SafeHandles.SafeFileHandle, Byte[], Int32, Int32, Int32, Int32 ByRef)
0035f318 79377ba0 System.IO.__ConsoleStream.Write(Byte[], Int32, Int32)
0035f338 793775ac System.IO.StreamWriter.Flush(Boolean, Boolean)
0035f350 79377b33 System.IO.StreamWriter.Write(Char[], Int32, Int32)
0035f370 79377a8d System.IO.TextWriter.WriteLine(System.String)
0035f388 793779aa System.IO.TextWriter+SyncTextWriter.WriteLine(System.String)
0035f394 00460251 WriteALot.Module1.Main()
0035f5b4 79e8273b [GCFrame: 0035f5b4]

Okay, so it was still writing to the standard output buffer. By dumping the stack objects I was then able to see how far along it had come:

0:000> !dso
OS Thread Id: 0x1db4 (0)
ESP/REG Object Name
0035f2b4 028dba08 Microsoft.Win32.SafeHandles.SafeFileHandle
0035f2c4 028dba08 Microsoft.Win32.SafeHandles.SafeFileHandle
0035f2fc 028dc338 System.Byte[]
0035f300 028dba1c System.IO.__ConsoleStream
0035f324 028dc0c8 System.IO.StreamWriter
0035f340 028dc0c8 System.IO.StreamWriter
0035f350 028e0b7c System.Char[]
0035f358 028dc0c8 System.IO.StreamWriter
0035f360 028e0b7c System.Char[]
0035f370 028e0a9c System.String 40 AAA BBB CCC DDD EEE FFF GGG HHH III JJJ KKK LLL MMM NNN OOO PPP QQQ RRR SSS TTT UUU VVV XXX YYY ZZZ
0035f37c 028dc448 System.IO.TextWriter+SyncTextWriter
0035f380 028e0a9c System.String 40 AAA BBB CCC DDD EEE FFF GGG HHH III JJJ KKK LLL MMM NNN OOO PPP QQQ RRR SSS TTT UUU VVV XXX YYY ZZZ
0035f388 028e0a9c System.String 40 AAA BBB CCC DDD EEE FFF GGG HHH III JJJ KKK LLL MMM NNN OOO PPP QQQ RRR SSS TTT UUU VVV XXX YYY ZZZ

So, apparently it was still trying to write the last line. There's nothing in the stack suggesting any behaviors out of the ordinary, so I turned my attention to the winforms application:

0:006> !threads
ThreadCount: 2
UnstartedThread: 0
BackgroundThread: 1
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
PreEmptive GC Alloc Lock
ID OSID ThreadOBJ State GC Context Domain Count APT Exception
0 1 1cb4 00539198 2006020 Enabled 029ec3ec:029edfe8 005355e8 0 STA
2 2 1854 00549578 b220 Enabled 00000000:00000000 005355e8 0 MTA (Finalizer)

0:006> ~0s
eax=00000000 ebx=00000000 ecx=00000000 edx=00000000 esi=003deab0 edi=00000000
eip=7735ab1d esp=003dea70 ebp=003dead4 iopl=0 nv up ei pl nz na po nc
cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000202
ntdll!NtDelayExecution+0x15:
7735ab1d c20800 ret 8

0:000> !clrstack
OS Thread Id: 0x1cb4 (0)
ESP EIP
003debb4 7735ab1d [HelperMethodFrame: 003debb4] System.Threading.Thread.SleepInternal(Int32)
003dec08 002c1073 StandardOutTest.Form1.WriteALot(Int32)
003dec3c 002c0f54 StandardOutTest.Form1.btnWrite_Click(System.Object, System.EventArgs)
003dec70 7b0693eb System.Windows.Forms.Control.OnClick(System.EventArgs)
003dec80 7b1065e9 System.Windows.Forms.Button.OnClick(System.EventArgs)
003dec8c 7b1066ef System.Windows.Forms.Button.OnMouseUp(System.Windows.Forms.MouseEventArgs)
003decb0 7b0d16ef System.Windows.Forms.Control.WmMouseUp(System.Windows.Forms.Message ByRef, System.Windows.Forms.MouseButtons, Int32)
003ded0c 7b062a8f System.Windows.Forms.Control.WndProc(System.Windows.Forms.Message ByRef)
003ded10 7b08512b [InlinedCallFrame: 003ded10]
003dedac 7b08504b System.Windows.Forms.Button.WndProc(System.Windows.Forms.Message ByRef)
003dedb4 7b06237d System.Windows.Forms.Control+ControlNativeWindow.OnMessage(System.Windows.Forms.Message ByRef)
003dedb8 7b062466 System.Windows.Forms.Control+ControlNativeWindow.WndProc(System.Windows.Forms.Message ByRef)
003dedcc 7b05e605 System.Windows.Forms.NativeWindow.Callback(IntPtr, Int32, IntPtr, IntPtr)
003def74 00110a6c [NDirectMethodFrameStandalone: 003def74] System.Windows.Forms.UnsafeNativeMethods.DispatchMessageW(MSG ByRef)
003def84 7b061c9a System.Windows.Forms.Application+ComponentManager.System.Windows.Forms.UnsafeNativeMethods.IMsoComponentManager.FPushMessageLoop(Int32, Int32, Int32)
003df024 7b0620f1 System.Windows.Forms.Application+ThreadContext.RunMessageLoopInner(Int32, System.Windows.Forms.ApplicationContext)
003df090 7b062293 System.Windows.Forms.Application+ThreadContext.RunMessageLoop(Int32, System.Windows.Forms.ApplicationContext)
003df0c0 7b0c7a5d System.Windows.Forms.Application.Run(System.Windows.Forms.ApplicationContext)
003df0c8 5e450ea8 Microsoft.VisualBasic.ApplicationServices.WindowsFormsApplicationBase.OnRun()
003df0f4 5e451c34 Microsoft.VisualBasic.ApplicationServices.WindowsFormsApplicationBase.DoApplicationModel()
003df120 5e450606 Microsoft.VisualBasic.ApplicationServices.WindowsFormsApplicationBase.Run(System.String[])
003df17c 002c018a StandardOutTest.My.MyApplication.Main(System.String[])
003df3bc 79e8273b [GCFrame: 003df3bc]

Apparently the winforms application was caught in the System.Threading.Thread.Sleep(10) - call. I therefore altered the application so that it would gradually read from the standard output buffer instead of trying to read it all at the end of execution:

Private Function WriteALot(ByVal iLines As Integer) As String
   Dim Output As String = ""
   Dim pSI As New Diagnostics.ProcessStartInfo(".\WriteALot.exe", iLines.ToString)
   With pSI
      .UseShellExecute = False
      .RedirectStandardError = True
      .RedirectStandardOutput = True
      .CreateNoWindow = True
      .LoadUserProfile = False
   End With
   Dim srOutput, srErr As IO.StreamReader
   Dim p As New System.Diagnostics.Process
   p.StartInfo = pSI
   Try
      p.Start()
      srOutput = p.StandardOutput
      srErr = p.StandardError
      'Loop the thread until the process has completed
      While Not p.HasExited
         System.Threading.Thread.Sleep(10)
         Output += srOutput.ReadToEnd()
         If Not p.Responding Then p.Kill()
      End While
      Output += srOutput.ReadToEnd
      srOutput.Dispose()
      srErr.Dispose()
      Catch ex As Exception
      Output = "Error: " & ex.Message
   Finally
      pSI = Nothing
      p.Dispose()
   End Try
   Return Output
End Function

This resolved the problem beautifully, so apparently I had identified the root cause.  I searched for documented limits and pretty quickly I came up with the answer. Once you know what to look for it is actually quite well documented on MSDN.

Until next time!

/ Johan