Asynchronous behavior of implicit Format-Table use can lead to data loss via the CLI

[mklement0]

Note: The root cause is the same as for #4594, which describes it in detail; the Start-Transcript-focused #10994 may be related too.

In short: the asynchronous behavior of implicitly applied Format-Table formatting (for types without explicit format data) has surprising side effects; while #4594 only describes more or less cosmetic issues, there is potential data loss here:

If a throw or exit statement comes before the asynchronous table output's delay has elapsed, that output as well as any subsequent output is never displayed.

While this is disconcerting enough interactively, it is very problematic when output from a call to PowerShell's CLI is being logged.

This SO question shows that the problem happens in real life; that question's author made the following points there:

• checking the log of an important overnight job run, key info about things happening just before an error is missing because of this bug. Also the missing info makes it look like the error occurred at a different point in the script.

• introducing an async delay seems like cheating. [...] If they really wanted to wait 300ms to sample data, that delay should occur synchronously.

The variant manifestation with exit was discovered in this SO answer.

Steps to reproduce

With throw

pwsh -noprofile -c @'
  'before'
  [pscustomobject] @{ foo = 1 }
  'after'
  throw "error"
'@

Same symptom with exit:

pwsh -noprofile -c @'
  'before'
  [pscustomobject] @{ foo = 1 }
  'after'
  exit
'@

Expected behavior

All objects output before the throw statement should show, 'before', the table-formatted custom object, and 'after' (ditto for the exit variation, except for the error message):

before

foo
---
  1
after
Exception:
Line |
   4 |    throw error
     |    ~~~~~~~~~~~
     | ScriptHalted

Actual behavior

All output starting with the implicitly table-formatted [pscustomobject] @{ foo = 1 } statement is lost:

before

Exception:
Line |
   4 |    throw error
     |    ~~~~~~~~~~~
     | ScriptHalted

Environment data

PowerShell Core 7.1.0-rc.2

[codeulike]

As this issue is here I'll write a little narrative about how it tripped me up. It might help make it more understandable.

I had an impotant overnight job, a Powershell script kicked off by the SQL Server Agent. As its an unsupervised batch job, I'm getting it to log info to a text file so that if something goes wrong I have a trail of info to figure out what happened.

And normally I would not expect an error to stop previous statements from writing their output. e.g with this code:

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

... I know that the 'pretend error' exception wont stop the statements above from appearing in the log.

Unfortunately for me, at one point in my batch job, I was collating some info into an array of objects, and then outputting those objects to the log. I was pleased to find that when you do that, Powershell outputs the object properties in a smart little table. It turns out - completely unbeknownst to me at the time - that powershell is implicitly using Format-Table to do that. And weirdly, that means the output then becomes asynchronous because a 300ms delay gets introduced. So the output kindof gets paused while my powershell script continues to execute. As I said, I had no idea at the time, and this to me seems like VERY WEIRD behaviour, for a scripting language to suddenly switch its ouput into asynchronous mode for completely opaque reasons.

So in code, I was creating an array of objects, filling in the properties and then outputing them. Something along these lines:

Write-Output ("test output 1")
Write-Output ("test output 2")
Write-Output ("test output 3")
$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 4")
Write-Output ("test output 5")
throw "pretend error"

So if you run that little snippet, you dont see any of the output after "test output 3". Thats pretty bonkers. The single most important thing I want my scripting language to do is execute the statements one after the other. But in this example it goes all parallel on me for no good reason.

So in the real world this caused me a right headache because my overnight batch file was failing, but when I looked in the log the error message was appearing but the previous five or six log messages I expected to see were missing. This meant the key info I needed to interpret the error message was missing. It also made it look like the error was happening at an earlier point in the script than it really was. It was a bit of a nightmare to untangle all that.

For reference, heres the SO question that helped me get to the bottom of it all:

Write-Output of array goes missing if error thrown afterwards

[microsoft-github-policy-service]

This issue has not had any activity in 6 months, if this is a bug please try to reproduce on the latest version of PowerShell and reopen a new issue and reference this issue if this is still a blocker for you.

[microsoft-github-policy-service]

This issue has not had any activity in 6 months, if this is a bug please try to reproduce on the latest version of PowerShell and reopen a new issue and reference this issue if this is still a blocker for you.

[microsoft-github-policy-service]

This issue has not had any activity in 6 months, if this is a bug please try to reproduce on the latest version of PowerShell and reopen a new issue and reference this issue if this is still a blocker for you.

[microsoft-github-policy-service]

This issue has been marked as "No Activity" as there has been no activity for 6 months. It has been closed for housekeeping purposes.