Powershell: Asynchronous behavior of implicit Format-Table use can have surprising side effects - console output may appear out of order

[mklement0]

^{A follow-up to #4552.}

Reference https://windowsserver.uservoice.com/forums/301869-powershell/suggestions/14925213-bug-console-output-appears-out-of-order

Users have been stumbling over this for a while (see this 2-year-old connect.microsoft.com bug report and various SO questions).

@PetSerAl provides an in-depth explanation of the problem in this SO answer.

In short, he states that, starting in PSv5, an _implicitly_ applied Format-Table call now waits 300 ms. before producing output in order to collect a reasonable number of objects to output so as to better determine suitable column widths.

That means that subsequent commands get to execute before the Format-Table output kicks in, which results in surprising behavior if these commands produce non-pipeline display output (e.g., with Write-Host) or prompt for user input, for instance.

_Update_: A related problem (irrespective of whether the asynchronous output is a problem) is that the implicit output formatting applied to the first command in a script locks in the implicit formatting for all remaining commands, which, if Format-Table is locked in, can lead to objects output by subsequent commands "disappearing", as originally detailed in #4552 (e.g.,
[pscustomobject] @{ one = 1; two = 2}; [pscustomobject] @{ three = 3} makes the 2nd custom object "disappear", because it doesn't share any properties with the 1st one) - see also: #12825

Steps to reproduce

[pscustomobject] @{ one = 1 }  # implicit Format-Table call - in PSv5+, waits 300 ms. before outputting
'hi' | Out-Host # explicit, synchronous, non-pipeline output
Read-Host -Prompt 'Press any key'

Expected behavior

PSv4- produces (note how the implicit Format-Table output comes _after_ the prompt):

one
---
  1
hi
Press any key:

Actual behavior

PSv5+ produces:

hi
Press any key:
one
---
  1

Environment data

PowerShell Core v6.0.0-beta.5 on macOS 10.12.6
PowerShell Core v6.0.0-beta.5 on Ubuntu 16.04.3 LTS
PowerShell Core v6.0.0-beta.5 on Microsoft Windows 10 Pro (64-bit; v10.0.15063)
Windows PowerShell v5.1.15063.483 on Microsoft Windows 10 Pro (64-bit; v10.0.15063)

[SteveL-MSFT]

The current behavior is by design. If this is a functional issue, I suppose we could have -AutoSize:$false not have the timer

[mklement0]

@SteveL-MSFT:

Re as-designed: I assumed as much, but it's another gotcha that calls for Documentation-Needed.

Re -AutoSize: Note that the problem only occurs with _implicit_ use of Format-Table. If you use ... | Format-Table explicitly - whether with or without -AutoSize - there is no asynchronous behavior.

Or are we talking about different things?

[PetSerAl]

Re -AutoSize: Note that the problem only occurs with implicit use of Format-Table. If you use ... | Format-Table explicitly - whether with or without -AutoSize - there is no asynchronous behavior.

& {
    [pscustomobject] @{ one = 1 }  # implicit Format-Table call - in PSv5+, waits 300 ms. before outputting
    'hi' | Out-Host # explicit, synchronous, non-pipeline output
    Read-Host -Prompt 'Press any key'
} | Format-Table

[iSazonov]

It seems internally we call Format-Default in the case.

[mklement0]

@PetSerAl:

Good point, but what I meant was applying Format-Table directly to the command that would otherwise trigger the asynchronous behavior (under the assumption that that command does _not_ have embedded pipeline-bypassing host operations):

[pscustomobject] @{ one = 1 } | Format-Table # outputs synchronously
'hi' | Out-Host # explicit, synchronous, non-pipeline output
Read-Host -Prompt 'Press any key'

Now that I think about it, even that use of Format-Table to force synchronous output can be problematic, because - while fine for _display_ - it replaces the original objects with _formatting objects_ in the pipeline.

[iSazonov]

It is dup #1747

[mklement0]

@iSazonov:

Indeed it is, thanks - due to its generic title, I didn't discover it.

Given that this issue describes the problem more specifically and includes a command to reproduce it, can I suggest we instead close #1747 as a duplicate?

Here's its summary:

@Jaykul states:

Isn't that the expected result of the delay in Format-Table to get widths for auto-size?
Do people want to give up that feature to "fix" this oddness in output?

@SteveL-MSFT states:

This is the side effect of the change we made. @LeeHolmes made the initial change so that we can compute more usable column widths based on objects returned within the first [N units of time].

@lzybkr states:

Principle of least surprise - output comes in the order it was written.

This doesn't mean giving up the feature, it just means flushing what was buffered before writing the other stream.

@joeyaiello states:

This is annoying, but I don't think it's a ship blocker.

[iSazonov]

1. We can check type output object and flush if the type changed.
2. After ending every pipeline we do some cleanups - at time we can flush the cache too. (We do the same for progress bar hiding.)

Currently I don't know what way is better.

[jszabo98]

I had the idea of a -NoWait parameter for Format-Table. You could set it in advance with $PSDefaultParameterValues, like setting -Encoding to Ascii for Out-File and '>'. Plus -NoWait's very existence would help document this behavior. By the way, in a script, implicitly run format-table could wait any amount of time for the second object before showing output.

# no output until script finishes
foreach ($i in 1..60) { 
  if ($i -eq 1) { [pscustomobject]@{message = $i} } 
  sleep 1
}

[iSazonov]

Really Format-Table doesn't do any delay, it only creates formatting objects.
The delay cache is initialized here: https://github.com/PowerShell/PowerShell/blob/ca202da6437f5c9ed334725469f6d8f1cb7e5a2c/src/System.Management.Automation/FormatAndOutput/common/BaseOutputtingCommand.cs#L158

and implemented here as a queue:
https://github.com/PowerShell/PowerShell/blob/ca202da6437f5c9ed334725469f6d8f1cb7e5a2c/src/System.Management.Automation/FormatAndOutput/common/OutputQueue.cs#L71-L77

If we could send a message and catch it in the condition we could resolve the issue.
The message could be dummy GroupEndData.
So we should only get understanding where from and when we could send the message.

[yecril71pl]

The following test fails, as of PSVersion 7.0.2

-SPLIT ([CONSOLEKEYINFO], [VERSION] | % { NEW-OBJECT $_ } | OUT-STRING) | SHOULD -CONTAIN 'MAJOR'

A partial workaround would be to put a ref object at the beginning of the pipeline, e.g.:

& { [VERSION]
NEW-OBJECT CONSOLEKEYINFO
READ-HOST }

This causes the default formatter to switch to FORMAT-LIST and also flushes the output. Why it is so remains a mystery.

[mklement0]

@yecril71pl, this is an unrelated issue: what you're seeing is that in (potentially implicit, as in this case) Format-Table formatting the _first_ object locks in the display columns - see https://stackoverflow.com/a/45705068/45375 and https://stackoverflow.com/a/55504393/45375

Stack Overflow

Powershell Custom Object Confusion

I was working on a script trying to output two different custom objects; one after another and was having problems, so to simplify, I stripped all the code down to just the minimum: $beep = new-ob...

Stack Overflow

Why is the output format changed when running two PowerShell commands in one line?

I'm getting unexpected results when executing two PowerShell commands separated by a semicolon. The output of the second command changes. If I run them in reverse order, I don't see the second comm...

[yecril71pl]

@yecril71pl, this is an unrelated issue:

Related, and by yourself: https://github.com/PowerShell/PowerShell/issues/4552#issuecomment-324106859 . Besides, as you may wish to have noticed, my workaround also resolves the READ-HOST flushing problem.

[mklement0]

It is only related in the abstract sense that is also a surprising Format-Table behavior, but I forgot that I actually "parked" this _technically_ unrelated issue in the OP - but only because the original issue, #4552 , was closed.
Later, #12825 was created, which contains further discussion.

Your workaround isn't one, because none is required for the types in your example (because they have formatting data associated with them), and it is ineffective for types that do need a workaround:

# NOT a workaround: Read-Host prompts first.
& { 
  [pscustomobject] @{ one = 1; two = 2; three = 3 }
  READ-HOST 
}

[yecril71pl]

Workaround:

& { 
[VERSION]
  [pscustomobject] @{ one = 1; two = 2; three = 3 }
  READ-HOST 
}

Works like a charm 😺

[mklement0]

It's still not a workaround: It only _happens_ to work, because [version] is of a type (System.RuntimeType) that has formatting data associated with it, in which case the asynchronous behavior doesn't occur.
(As an aside: the use of & { ... } makes no difference here.)

If you use a second [pscustomobject] [_update_: _instead_ of [version]) or output the [pscustomobject] _first_, for instance, Read-Host will again prompt first.

The only way to _always_ avoid the asynchronous behavior is to pipe to Out-Host or an explicit Format-* call (in which case nothing is written to the pipeline) or to pipe to Out-String (in which case you output a _string_ to the pipeline).

[PetSerAl]

@yecril71pl This issue exists only in v5+, but yours behave that way since v1.

[yecril71pl]

(As an aside: the use of & { ... } makes no difference here.)

The block is necessary if you paste it into the console.

If you use a second [pscustomobject], for instance, Read-Host will again prompt first.

Geez, dude, who do you think I am?

& { 
[VERSION]
  [pscustomobject] @{ one = 1; two = 2; three = 3 }  
  [pscustomobject] @{ one = 1; two = 2; three = 3 }
  READ-HOST 
}

IsPublic IsSerial Name BaseType
-------- -------- ---- --------
True True Version System.Object

one : 1
two : 2
three : 3

one : 1
two : 2
three : 3

MY INPUT
MY INPUT

As I said, [VERSION] must go first, otherwise the workaround does not work.

The only way to _always_ avoid the asynchronous behavior is to pipe to Out-Host or an explicit Format-* call (in which case nothing is written to the pipeline) or to pipe to Out-String (in which case you output a _string_ to the pipeline).

If I ever encounter a situation where the workaround does not work, I shall report back, with your permission.

[mklement0]

I meant: use a second [pscustomobject] _instead_ of [version], but the problem is more easily demonstrated simply by _reversing the output order_:

# Does NOT work: Read-Host prompts first.
& { 
  [pscustomobject] @{ one = 1; two = 2; three = 3 }
  [VERSION]
  READ-HOST 
}

I don't think having to place an unrelated object whose type has associated formatting data, just so that it triggers synchronous output behavior (and obviously becomes part of the output), qualifies as a workaround.

There currently is no good workaround: you're forced to choose between synchronous display (e.g., via Out-Host), which means there'll be no pipeline output, and having pipeline input with asynchronous display.

---

On a meta note:

Geez, dude, who do you think I am?

We are discussing technical issues here, not personalities.
Please refrain from such flippancy in the future.

[yecril71pl]

I meant: use a second [pscustomobject] _instead_ of [version], but the problem is more easily demonstrated simply by _reversing the output order_:

As I said, [VERSION] must go first, otherwise it does not work. If I had used a custom object instead of [version], it would have become the _first_ one.

I don't think having to place an unrelated object whose type has associated formatting data, just so that it triggers synchronous output behavior (and obviously becomes part of the output), qualifies as a workaround.

I appreciate your disgust, however, it is sufficient for me and I do not know anything better.

On a meta note:

Geez, dude, who do you think I am?

We are discussing technical issues here, not personalities.
Please refrain from such flippancy in the future.

It would have been blatantly incompetent of me if I had not checked that the workaround works with two objects in the pipeline.

[SeeminglyScience]

It would have been blatantly incompetent of me if I had not checked that the workaround works with two objects in the pipeline.

Nah just would have been a mistake, we all make 'em.

It's also pretty much impossible to judge someone's competency from a handful of issues. Even harder to actually keep a mental map of exactly how competent every single community member is.

[mklement0]

Excellent point, @SeeminglyScience.

Additionally, in this specific case, the instruction given by me that triggered @yecril71pl's response was misinterpreted:

The instruction was poorly phrased (since corrected), but the paragraph that preceded it should have made it clear that the issue is not about _how many_ objects there are in the pipeline, but _whether or not the type of the FIRST one happens to have associated formatting data_.

And that distinction is indeed quite subtle, not something anyone could be expected to recognize readily.

Therefore: We all make mistakes, and we all misinterpret others' comments on occasion. This only becomes problematic if one takes things _personally_.

@yecril71pl , another problematic aspect is to use incendiary language such as "I appreciate your disgust"; it adds nothing to the discussion and serves merely to antagonize.