Process.StandardOutput.Readline() is hanging when there is no output

Question

Note: I am trying to run packer.exe as a background process to workaround a particular issue with the azure-arm builder, and I need to watch the output. I am not using
Start-Process because I don't want to use an intermediary file to consume the output.

I have the following code setting up packer.exe to run in the background so I can consume its output and act upon a certain log message. This is part of a larger script but this is the bit in question that is not behaving correctly:

  $builderDir = ( Split-Path -Parent $PSCommandPath )
  Push-Location $builderDir
  
  # Set up the packer command to run asynchronously
  $pStartProps = @{
    FileName               = ( Get-Command -CommandType Application packer ).Source
    Arguments              = "build -var-file ""${builderDir}\win-dev.pkrvars.hcl"" -only ""azure-arm.base"" ."
    UseShellExecute        = $false
    RedirectStandardOutput = $true
    RedirectStandardError  = $false
    LoadUserProfile        = $true
  }
  $pStartInfo = New-Object ProcessStartInfo -Property $pStartProps

  $p = [Process]::Start($pStartInfo)

  while ( $null -ne ( $output = $p.StandardOutput.Readline() ) -or !$p.HasExited ) {
    # Do stuff
  }

Basically, the ( $output = $p.StandardOutput.Readline() ) portion of the while condition seems to be hanging until there is more output to be read. I'm not sure why this is, because StreamReader.Readline() should either return the next line to be read, or null if there is no more output. I have a fair bit of processing around this regarding the log message I'm expecting to get, so blocking when reading STDOUT when there is no further output to consume renders the script useless. There are other things it is doing in the foreground while packer.exe continues to execute.

I am able to confirm in the debugger that Readline() does read empty lines (value of "") fine, this seems to happen be when there is not yet further output to consume. This may be tangential but this causes the debugger to bug out as well.

When this issue occurs the VSCode debugger sits on this with
$output = $p.StandardOutput.Readline() highlighted for a few seconds, then the debugger stops (everything disappears, no more variable tracking, etc.) until Readline() stops blocking and execution continues, at which point the debugger seems to re-initialize the tracked variables, watched expressions, etc. So I can't use the debugger at all when this occurs. Even the
PowerShell Integrated Console (the one used with the debugger) hangs and I cannot type anything.

---

For full context, the goal of this script is to let packer.exe do its thing while I loop continuously to:

1. Display more output from packer.exe
2. Check for the presence of a certain log message
3. Give packer.exe a bit of time to try to do what it needs on its own
4. If it waits too long, I execute a script against the node being since what packer.exe should have done on its own likely failed
   • I am using Invoke-AzVMRunCommand to do this, which can't be done at the state packer.exe for the issue I am working around. It must be performed out-of-band of the packer.exe run itself.
5. The build continues on after the workaround is applied and I simply continue forwarding the output of packer.exe to the console until the process exits

But since the script hangs when there is no output, step 4 will never work as I have to give packer time to try to complete the config on its own, and is the entire reason why I'm hacking this together in the first place.

---

Why is Readline() blocking here? Am I doing something incorrectly? This behavior occurs whether I run my script in Windows PowerShell or PowerShell Core.

Answer 1

• StreamReader.ReadLine() is blocking by design.

• There is an asynchronous alternative, .ReadLineAsync(), which returns a Task<string> instance that you can poll for completion, via its .IsCompleted property, without blocking your foreground thread (polling is your only option in PowerShell, given that it has no language feature analogous to C#'s await).

Here's a simplified example that focuses on asynchronous reading from a StreamReader instance that happens to be a file, to which new lines are added only periodically; use Ctrl-C to abort.

I would expect the code to work the same if you adapt it to your stdout-reading System.Diagnostics.Process code.

# Create a sample input file.
$n=3
1..$n > tmp.txt

# Open the file for reading, and convert it to a System.IO.StreamReader instance.
[IO.StreamReader] $reader = 
  [IO.File]::Open("$pwd/tmp.txt", 'Open', 'Read', 'ReadWrite')

try {
  $task = $reader.ReadLineAsync() # Start waiting for the first line.
  while ($true) { # Loop indefinitely to wait for new lines.
    if ($task.IsCompleted) {  # A new line has been received.
      $task.Result # Output
      # Start waiting for the next line.
      $task.Dispose(); $task = $reader.ReadLineAsync(); 
    }
    else { # No new line available yet, do other things.
      Write-Host '.' -NoNewline
      Start-Sleep 1
    }
    # Append a new line to the sample file every once in a while.
    if (++$n % 10 -eq 0) { $n >> tmp.txt }
  }
}
finally {
  $reader.Dispose()
}

Answer 2

The StreamReader from standard output is waiting for IO - the stream from StandardOutput can't get opened for reading until it gets more data or the Process is closed. There's a similar issue with using StreamReader on TCP streams, where you get to enjoy waiting for network traffic.

The usual way around it is to let a different task wait on it via async reads like ReadLineAsync(). This doesn't help your while loop, because it still sits and waits the same amount before it can progress to read the output's StreamReader.

If packer.exe's output behaves well, you can try using a powershell job's output property instead of [process]? I tested with ping that gives the same waiting-for-IO lockup behavior:

# Locks up for full ping timeout example: 
$pStartProps = @{ FileName  = 'ping.exe' ; Arguments = '10.bad.ip.0' ... }
$p = [System.Diagnostics.Process]::Start($pStartInfo)

# Locks when reading
$output = $p.StandardOutput.ReadLine()
while ( $output -ne $null ) {
  $output = $p.StandardOutput.ReadLine(); ## read the output
  # Do stuff
}

#####

# Does not lock when using Job output instead:
$job = Start-Job -ScriptBlock { ping.exe 10.bad.ip.0 }

While ($job.State -ne 'Completed') {
  $job.ChildJobs[0].Output  ## read the output
  # Do stuff
}

Answer 3

Using StandardOutput.ReadLine() as above, you set the Output redirection stream to use Synchronous read mode. This means that when you call $p.StandardOutput.ReadLine() it behaves like a normal function call.

You call it, and wait for the return value. The return value is either a complete line or $null if the end of stream is reached. This means that as the running program fills the System.Diagnostics.Process output stream buffer with output, you continue to be a good synchronous PowerShell boy and wait for the function call to return. Once the System.Diagnostics.Process detects a newline in the stream, the function call $p.StandardOutput.ReadLine() returns with your data, a full complete line.

This is why it seems like it is blocking. It has to wait till it has a full line before the function can return.

The other return value, $null, makes more sense knowing that a StreamReader object is used for many different things that could have different endings for the stream. If you were using a StreamReader to read a text file, the end of the stream/file is when you hit the EOF marker. If you were reading in an array of characters, it could be the \0 string terminator. $null in this case is a universal end of stream.

For a System.Diagnostics.Process object, it's definition of "the end of a stream" is when the process completes, not "I have no output at this moment".

In order to remove this blocking you have to perform your reading in an Asynchronous manner a.k.a. ReadLineAsync().

Not wanting to step on @mklement0 toes, as he, correctly, solves your problem by using ReadLineAsync() to make it Asynchronous, and by polling to keep the checking/validation script inside the same scope. But an alternative method to read data asynchronously is to use Process.BeginOutputReadLine() and the OutputDataReceived Event to Asynchronously fire off a Script Block when you have more data.

# Script to run when you have another line of data
$NewOutputSB = {
    param([object]$sender, [System.Diagnostics.DataReceivedEventArgs]$e)
    Write-Host "  #  " $e.Data
}

$pStartProps = @{
    FileName               = ( Get-Command -CommandType Application ping.exe ).Source
    Arguments              = "8.8.8.8"
    UseShellExecute        = $false
    RedirectStandardOutput = $true
    RedirectStandardError  = $false
    LoadUserProfile        = $true
}
$pStartInfo = New-Object System.Diagnostics.ProcessStartInfo -Property $pStartProps

$p = New-Object System.Diagnostics.Process

# Register the Event Handler
$EventSub = Register-ObjectEvent $p -EventName OutputDataReceived -Action $NewOutputSB

$p.StartInfo = $pStartInfo

$p.Start() | Out-Null

# Begin asynchronous reading on the Output stream
$p.BeginOutputReadLine()

# Do other work while we wait for it to finish running...
while ( !$p.HasExited ) {
    # Do stuff
    Start-Sleep -Milliseconds 250
    Write-Host "--- Do stuff"
}

# Cleanup Event Handler
Unregister-Event -SubscriptionId $EventSub.Id

After running this code, the Output shows the stream running in Asynchronous mode:

PS C:\>
  #   
  #   Pinging 8.8.8.8 with 32 bytes of data:
  #   Reply from 8.8.8.8: bytes=32 time=28ms TTL=119
--- Do stuff
--- Do stuff
--- Do stuff
  #   Reply from 8.8.8.8: bytes=32 time=28ms TTL=119
--- Do stuff
--- Do stuff
--- Do stuff
--- Do stuff
  #   Reply from 8.8.8.8: bytes=32 time=31ms TTL=119
--- Do stuff
--- Do stuff
--- Do stuff
--- Do stuff
  #   Reply from 8.8.8.8: bytes=32 time=28ms TTL=119
  #
  #   Ping statistics for 8.8.8.8:
  #       Packets: Sent = 4, Received = 4, Lost = 0 (0% loss),
  #   Approximate round trip times in milli-seconds:
  #       Minimum = 28ms, Maximum = 31ms, Average = 28ms
  #
--- Do stuff