Powershell Write-Output of array goes missing if error thrown afterwards

Question

Right so in Powershell if you Write-Output some lines and then throw an error, you'd expect to get the output that happens before the error. So if you execute this:

Write-Output ("test output 1")
Write-Output ("test output 2")
Write-Output ("test output 3")
Write-Output ("test output 4")
Write-Output ("test output 5")
throw "pretend error"

You will get this as expected:

test output 1
test output 2
test output 3
test output 4
test output 5
pretend error
At C:\Powershell\Test.ps1:7 char:1
+ throw "pretend error"
+ ~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : OperationStopped: (pretend error:String) [], RuntimeException
    + FullyQualifiedErrorId : pretend error

However if you Write-Output a bunch of objects in an array, and then afterwards throw an error, the Write-Output of the array (and anything after that) never appears. So if you run this:

Write-Output ("test output 1")
Write-Output ("test output 2")
Write-Output ("test output 3")
Write-Output ("test output 4")
Write-Output ("test output 5")
$testlist = @()
$count = 1
While($count -lt 6)
{
    $testobj = new-object psobject -prop @{Name="array object $count"}
    $testlist += $testobj
    $count +=1
}
Write-Output $testlist 
Write-Output ("test output 6")
Write-Output ("test output 7")
throw "pretend error"

... you dont get any of the output after "test output 5". Its as if outputting the array makes everything get buffered and then the error loses the buffer. Something to do with the way Powershell uses pipes with arrays?

So my question is: what do I need to do to make sure the Write-Output doesn't get lost due to subsequent errors. This makes logging really difficult.

This is in Powershell 5.1

Answer 1

It looks like you're seeing a very unfortunate side effect of the problematic 300-millisecond delay that was introduced to implicit use of Format-Table in PowerShell v5 in order to better calculate suitable column widths, which is detailed in this answer and discussed in GitHub issue #4594; however, your symptom is so problematic that it warrants a new bug report: GitHub issue #13985.

Because your $testlist array contains objects that have fewer than 4 properties (namely just one in your case) and because the type of your objects ([pscustomobject]) has no formatting data associated with it, PowerShell implicitly uses Format-Table for output formatting.

By the time the throw statement is encountered, the 300-millisecond delay has not elapsed yet, and because throw terminates the runspace^[1], the Format-Table output (and the subsequent Write-Output output) are never shown.

The - imperfect - workaround is to force output to be synchronous, which can be done with one of three ways:

• Use Out-Host, which uses the default output behavior synchronously, but it also means that from inside PowerShell you won't be able to capture or redirect the output; however, when called from the outside, via PowerShell's CLI, Out-Host output goes to stdout and can be captured too.

• Use Format-Table explicitly. This also works fine for display, but changes the output from your data to unrelated objects that are formatting instructions, which PowerShell itself translates to the usual, rich display formatting, but these are useless if you wanted to capture the output - your original data is lost.

• If you want to least allow capturing the formatted string representations of your original objects from inside PowerShell, you can use Out-String, which outputs the formatted representation as a single, multi-line string (unfortunately, with an extra trailing newline); when called from outside PowerShell, the effect will in essence be the same as calling Out-Host.

Note that in your case the workaround need only be applied to the $testlist statement:

# Or ... | Out-Host or ... | Format-Table - see comments above.
$testlist | Out-String

There's an alternative, but more obscure workaround that relies on using Start-Sleep to wait at least 300 ms. and outputting at least one more object after the implicit Format-Table call, as demonstrated in this simplified example:

'before'
[pscustomobject] @{ foo = 1 }
Start-Sleep -Milliseconds 300  # wait for implicit Format-Table
'after' # force output of the table by outputting at least one more object
throw "error"

The advantage of this workaround is that your original objects are preserved in the output this way, which would allow you to capture them as such from inside PowerShell with, say,
$output = try { ./someScript.ps1 } catch { Write-Error $_ }

---

Finally, your code can be streamlined; to put it all together:

# Use *implicit* output - no need for Write-Output
# If you do use Write-Output: separate the arguments with *spaces*,
# don't put (...) around the argument list.
"test output 1"
# ...


# Implicitly capture the foreach loop output in an array.
# This is much more efficient than using += to "extend" an array
# in a loop (which requires creating a *new* array every time).
[array] $testlist = 
  foreach ($count in 1..6) {
    # Simpler and more efficient PSv3+ method for constructing
    # custom objects.
    [pscustomobject] @{ Name="array object $count" }
  }

# Apply the workaround.
$testlist | Out-String

# Use implicit output again.
"test output 6"
"test output 7"

throw "pretend error"

---

^{[1] That is, throw generates a runspace-terminating (script-terminating) error, which instantly aborts overall execution - unlike a statement-terminating error, which only aborts the statement at hand, such as would occur when an exception occurs in a .NET method call; You can convert all statement-terminating as well as all non-terminating errors to runspace-terminating ones by setting the $ErrorActionPreference preference variable to 'Stop' - see this answer.}

Answer 2

That's interesting. The way to ensure output is seen is the same way to ensure output is in the correct order when mixing Write-Host with Write-Output - use Out-Host after each line.

Write-Output ("test output 1") | Out-Host
Write-Output ("test output 2") | Out-Host
Write-Output ("test output 3") | Out-Host
Write-Output ("test output 4") | Out-Host
Write-Output ("test output 5") | Out-Host
$testlist = @()
$count = 1
While($count -lt 6)
{
    $testobj = new-object psobject -prop @{Name="array object $count"}
    $testlist += $testobj
    $count +=1
}
Write-Output $testlist  | Out-Host
Write-Output ("test output 6") | Out-Host
Write-Output ("test output 7") | Out-Host
throw "pretend error"

You could also enclose groups of lines in subexpression $(..) and do one Out-Host if that is suitable for the situation.

$(Write-Output ("test output 1")
Write-Output ("test output 2")
Write-Output ("test output 3")
Write-Output ("test output 4")
Write-Output ("test output 5")
$testlist = @()
$count = 1
While($count -lt 6)
{
    $testobj = new-object psobject -prop @{Name="array object $count"}
    $testlist += $testobj
    $count +=1
}
Write-Output $testlist
Write-Output ("test output 6")
Write-Output ("test output 7")) | Out-Host
throw "pretend error"