Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
mklement0 opened this issue Aug 16, 2017 · 33 comments
Labels
Resolution-No Activity Issue has had no activity for 6 months or more WG-Engine core PowerShell engine, interpreter, and runtime

Comments

@mklement0
Copy link
Contributor

mklement0 commented Aug 16, 2017

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
Copy link
Member

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

@SteveL-MSFT SteveL-MSFT added the WG-Engine core PowerShell engine, interpreter, and runtime label Aug 16, 2017
@mklement0
Copy link
Contributor Author

@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
Copy link
Contributor

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
Copy link
Collaborator

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

@mklement0
Copy link
Contributor Author

@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
Copy link
Collaborator

It is dup #1747

@mklement0
Copy link
Contributor Author

@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.

@mklement0 mklement0 changed the title Asynchronous behavior of implicit Format-Table use can have surprising side effects Asynchronous behavior of implicit Format-Table use can have surprising side effects - console output may appear out of order Aug 18, 2017
@iSazonov
Copy link
Collaborator

  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.

@SteveL-MSFT SteveL-MSFT added this to the 6.1.0 milestone Oct 1, 2017
Iristyle added a commit to Iristyle/bolt that referenced this issue Nov 6, 2017
 - The current WinRM specs use the Write-Output cmdlet. The
   Write-Output cmdlet is designed for writing objects to the
   PowerShell pipeline, *not* for writing stdout to a host.

   PowerShell has a few different methods of writing more directly to
   stdout, the most popular of which is Write-Host. Write-Host is
   typically frowned upon by the PowerShell community, but because it
   is not appropriate for use where pipelines may be involved:

   http://www.jsnover.com/blog/2013/12/07/write-host-considered-harmful/

   When the goal is to emit text to be consumed by other tooling that
   doesn't integrate with the PowerShell pipeline, Write-Host becomes
   an important tool, and likely the case the tests are interested in
   (independent ordered text-based writes to stdout).

   Such counterpoints are provided at:

   https://psitem.com/2015/01/16/is-write-host-really-harmful/

   The other alternatives to calling Write-Host are Out-Host,
   [Console]::WriteLine and the lesser known $Host.UI.WriteLine

 - While Write-Output can generate output for both stdout *and* for
   the PowerShell pipeline, there is also a problem with using it if
   output ordering is important.

   In PowerShell 5, changes were introduced to its behavior, so that
   implicit table formatting receives a 300ms delay. This often
   results in out-of-order output when Write-Output is used, and may
   especially be the case when pipeline writes with Write-Output are
   mixed with direct writes to stdout with Write-Host

   PowerShell/PowerShell#4594
   https://windowsserver.uservoice.com/forums/301869-powershell/suggestions/14925213-bug-console-output-appears-out-of-order
Iristyle added a commit to Iristyle/bolt that referenced this issue Nov 6, 2017
 - The current WinRM specs use the Write-Output cmdlet. The
   Write-Output cmdlet is designed for writing objects to the
   PowerShell pipeline, *not* for writing stdout to a host.

   PowerShell has a few different methods of writing more directly to
   stdout, the most popular of which is Write-Host. Write-Host is
   typically frowned upon by the PowerShell community, but because it
   is not appropriate for use where pipelines may be involved:

   http://www.jsnover.com/blog/2013/12/07/write-host-considered-harmful/

   When the goal is to emit text to be consumed by other tooling that
   doesn't integrate with the PowerShell pipeline, Write-Host becomes
   an important tool, and likely the case the tests are interested in
   (independent ordered text-based writes to stdout).

   Such counterpoints are provided at:

   https://psitem.com/2015/01/16/is-write-host-really-harmful/

   The other alternatives to calling Write-Host are Out-Host,
   [Console]::WriteLine and the lesser known $Host.UI.WriteLine

 - While Write-Output can generate output for both stdout *and* for
   the PowerShell pipeline, there is also a problem with using it if
   output ordering is important.

   In PowerShell 5, changes were introduced to its behavior, so that
   implicit table formatting receives a 300ms delay. This often
   results in out-of-order output when Write-Output is used, and may
   especially be the case when pipeline writes with Write-Output are
   mixed with direct writes to stdout with Write-Host

   PowerShell/PowerShell#4594
   https://windowsserver.uservoice.com/forums/301869-powershell/suggestions/14925213-bug-console-output-appears-out-of-order
Iristyle added a commit to Iristyle/bolt that referenced this issue Nov 7, 2017
 - The current WinRM specs use the Write-Output cmdlet. The
   Write-Output cmdlet is designed for writing objects to the
   PowerShell pipeline, *not* for writing stdout to a host.

   PowerShell has a few different methods of writing more directly to
   stdout, the most popular of which is Write-Host. Write-Host is
   typically frowned upon by the PowerShell community, but because it
   is not appropriate for use where pipelines may be involved:

   http://www.jsnover.com/blog/2013/12/07/write-host-considered-harmful/

   When the goal is to emit text to be consumed by other tooling that
   doesn't integrate with the PowerShell pipeline, Write-Host becomes
   an important tool, and likely the case the tests are interested in
   (independent ordered text-based writes to stdout).

   Such counterpoints are provided at:

   https://psitem.com/2015/01/16/is-write-host-really-harmful/

   The other alternatives to calling Write-Host are Out-Host,
   [Console]::WriteLine and the lesser known $Host.UI.WriteLine

 - While Write-Output can generate output for both stdout *and* for
   the PowerShell pipeline, there is also a problem with using it if
   output ordering is important.

   In PowerShell 5, changes were introduced to its behavior, so that
   implicit table formatting receives a 300ms delay. This often
   results in out-of-order output when Write-Output is used, and may
   especially be the case when pipeline writes with Write-Output are
   mixed with direct writes to stdout with Write-Host

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

 - Modify 2 tests so that Write-Host emits a single string with
   multiple embeds, rather than calling Write-Output with multiple
   string objects
Iristyle added a commit to Iristyle/bolt that referenced this issue Nov 7, 2017
 - The current WinRM specs use the Write-Output cmdlet. The
   Write-Output cmdlet is designed for writing objects to the
   PowerShell pipeline, *not* for writing stdout to a host.

   PowerShell has a few different methods of writing more directly to
   stdout, the most popular of which is Write-Host. Write-Host is
   typically frowned upon by the PowerShell community, but because it
   is not appropriate for use where pipelines may be involved:

   http://www.jsnover.com/blog/2013/12/07/write-host-considered-harmful/

   When the goal is to emit text to be consumed by other tooling that
   doesn't integrate with the PowerShell pipeline, Write-Host becomes
   an important tool, and likely the case the tests are interested in
   (independent ordered text-based writes to stdout).

   Such counterpoints are provided at:

   https://psitem.com/2015/01/16/is-write-host-really-harmful/

   The other alternatives to calling Write-Host are Out-Host,
   [Console]::WriteLine and the lesser known $Host.UI.WriteLine

 - While Write-Output can generate output for both stdout *and* for
   the PowerShell pipeline, there is also a problem with using it if
   output ordering is important.

   In PowerShell 5, changes were introduced to its behavior, so that
   implicit table formatting receives a 300ms delay. This often
   results in out-of-order output when Write-Output is used, and may
   especially be the case when pipeline writes with Write-Output are
   mixed with direct writes to stdout with Write-Host

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

 - Modify 2 tests so that Write-Host emits a single string with
   multiple embeds, rather than calling Write-Output with multiple
   string objects

 - Introduce additional test demonstrating ways of generating stdout
   in PowerShell - namely:

   Write-Output
      explicitly sent to Format-Table to avoid ordering issue
   Write-Host
   Out-Host
   $Host.UI.WriteLine
   [Console]::WriteLine
   Write-Information
@SteveL-MSFT SteveL-MSFT modified the milestones: 6.2.0-Consider, Future Jun 21, 2018
@jszabo98
Copy link

jszabo98 commented Dec 14, 2019

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
Copy link
Collaborator

iSazonov commented Dec 14, 2019

Really Format-Table doesn't do any delay, it only creates formatting objects.
The delay cache is initialized here:

_cache.EnableGroupCaching(callBack, TimeSpan.FromMilliseconds(300));

and implemented here as a queue:

// STATE TRANSITION: we are processing and we stop
if (_processingGroup &&
((o is GroupEndData) ||
(_objectCount > 0) && (_currentObjectCount >= _objectCount)) ||
((_groupingTimer != null) && (_groupingTimer.Elapsed > _groupingDuration))
)
{

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
Copy link
Contributor

yecril71pl commented Jul 16, 2020

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
Copy link
Contributor Author

mklement0 commented Jul 16, 2020

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
Copy link
Contributor

Workaround:

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

Works like a charm 😺

@mklement0
Copy link
Contributor Author

mklement0 commented Jul 16, 2020

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
Copy link
Contributor

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

@yecril71pl
Copy link
Contributor

(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
Copy link
Contributor Author

mklement0 commented Jul 16, 2020

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
Copy link
Contributor

yecril71pl commented Jul 16, 2020

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
Copy link
Collaborator

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
Copy link
Contributor Author

mklement0 commented Jul 16, 2020

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.

@metablaster
Copy link

Since this behavior happens only with [pscustomobject] do you suggest using [psobject] as an alternative since it doesn't have this problem?

I know psobject is somewhat slower and works slightly differently (ex. doesn't retain the order of members) but I it's still a good workaround, since there is no need to use hackery and should be easy to update existing code that makes use of pscustomobject.

@mklement0
Copy link
Contributor Author

@metablaster, the problem isn't specific to [pscustomobject] (which is technically the same as [psobject] - System.Management.Automation.PSObject), it affects all (non-primitive) .NET types that (a) do not have predefined formatting data associated with them and (b) trigger implicit Format-Table formatting due to having 4 or fewer properties; e.g.:

PS> [regex] ''; write-host hi  # !!  'hi' prints first

hi
Options RightToLeft MatchTimeout
------- ----------- ------------
   None       False -00:00:00.0010000

As an aside: Use of [psobject] in PowerShell code is best avoided; see this comment for background information on the unfortunate conflation of [psobject] and [pscustomobject].

@metablaster
Copy link

@mklement0

I took a look at your link where you said Use [System.Collections.Generic.List[object]], for my specific example in previous duplicate issue #14464 I tried with Dictionary<TKey,TValue> which unfortunately results in same unexpected behavior.

However your mention of "format data" solved all of my problems and I'm still sticking with PSCustomObject
I defined Format.ps1xml file with custom type and now all problems are gone 😄

Thanks so much!

foreach ($i in 1..3)
{
	Write-Information -MessageData "Performing operation $i" -INFA "Continue"

	[PSCustomObject]@{
		TemplateKey1 = "A$i"
		TemplateKey2 = "B$i"
		TemplateKey3 = "C$i"
                # Cutom type name for Format.ps1xml
		PSTypeName = "TestType"
	}
}

Actual AND expected behavior

Performing operation 1

TemplateKey1     TemplateKey2     TemplateKey3
------------     ------------     ------------
A1               B1               C1
Performing operation 2
A2               B2               C2
Performing operation 3
A3               B3               C3

@mklement0
Copy link
Contributor Author

@metablaster:

Glad to hear it. Yes, associating formatting data with any type avoids the problem.

Re:

you said Use [System.Collections.Generic.List[object]]

I should have made it clearer that this was an entirely incidental aspect of why I linked to that comment - I linked to it solely for the background information on [psobject] in the second section.

@mklement0
Copy link
Contributor Author

mklement0 commented Oct 3, 2021

A more insidious side effect of the asynchronous behavior is that CLI calls from outside PowerShell can result in data loss due to missing output - see this Stack Overflow question and

Copy link
Contributor

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.

1 similar comment
Copy link
Contributor

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 microsoft-github-policy-service bot added Resolution-No Activity Issue has had no activity for 6 months or more labels Nov 16, 2023
Copy link
Contributor

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.

Copy link
Contributor

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

@jszabo98
Copy link

Glad to see all these bugs have been resolved.

@metablaster
Copy link

Glad to see all these bugs have been resolved.

lol, reminds me of one reason for not resolving a bug from GNU mailing list labeled as "Nobody cares"

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Resolution-No Activity Issue has had no activity for 6 months or more WG-Engine core PowerShell engine, interpreter, and runtime
Projects
None yet
Development

No branches or pull requests

8 participants