Powershell: Receive-Job duplicates Write-Host output from background job

[splatteredbits]

If $InformationPreference is Continue, the Receive-Job cmdlet duplicates Write-Host output from background jobs.

Steps to reproduce

> Start-Job { 1..5 | % { Write-Host $_ } } | Wait-Job | Receive-Job -InformationAction Continue
1
1
2
2
3
3
4
4
5
5

or

> $InformationPreference = 'Continue'
> Start-Job { 1..5 | % { Write-Host $_ } } | Wait-Job | Receive-Job
1
1
2
2
3
3
4
4
5
5

Expected behavior

> Start-Job { 1..5 | % { Write-Host $_ } } | Wait-Job | Receive-Job -InformationAction Continue
1
2
3
4
5

Environment data

> $PSVersionTable
Name                      Value
----                      -----
PSVersion                 6.1.0
PSEdition                 Core
GitCommitId               6.1.0
OS                        Microsoft Windows 6.1.7601 S
Platform                  Win32NT
PSCompatibleVersions      {1.0, 2.0, 3.0, 4.0...}
PSRemotingProtocolVersion 2.3
SerializationVersion      1.1.0.1
WSManStackVersion         3.0

[splatteredbits]

This also affects Windows PowerShell 5.1: https://windowsserver.uservoice.com/forums/301869-powershell/suggestions/35443981-receive-job-duplicates-write-host-output

[thezim]

This does not repro for me on Windows PowerShell.

PS C:\temp> Start-Job { 1..5 | % { Write-Host $_ } } | Wait-Job | Receive-Job
1
2
3
4
5
PS C:\temp> $PSVersionTable

Name                           Value
----                           -----
PSVersion                      5.1.14393.2368
PSEdition                      Desktop
PSCompatibleVersions           {1.0, 2.0, 3.0, 4.0...}
BuildVersion                   10.0.14393.2368
CLRVersion                     4.0.30319.42000
WSManStackVersion              3.0
PSRemotingProtocolVersion      2.3
SerializationVersion           1.1.0.1

[iSazonov]

@thezim Do you set $InformationPreference to Continue?

[mklement0]

Indeed, @thezim:

It is adding -InformationAction Continue to the Receive-Job call that produces the symptom, or setting $InformationActionPreference = 'Continue' beforehand.

[PetSerAl]

One copy came from host stream. Another from information stream.

[vexx32]

Host is information stream as of... PS v5 and up, I believe. :)

[PetSerAl]

@vexx32 Host stream is separate from information stream. Also, host stream is bidirectional.

Start-Job {
    $Host.UI.Write('Input value: ')
    $Host.UI.WriteLine('Value from main process: ' + $Host.UI.ReadLine())
} | Receive-Job -Wait -AutoRemoveJob

[vexx32]

Right, but that's not what the issue is really about. They're using Write-Host, which does write to the information stream.

So I guess the issue is that the tagged messages write to the host stream and then write to the host stream again when as they pass through receive-job with its specified InformationAction...

[PetSerAl]

@vexx32 Processing information record in job cause it to produce host message, which received alongside with information record. Now, when information record processed locally, it can produce another host message. Which is what happening here.

[PetSerAl]

Just to demonstrate this:

Start-Job {
Start-Job {
Start-Job {
Start-Job {
Start-Job {
    Write-Information Test -InformationAction Continue
} | Receive-Job -Wait -AutoRemoveJob -InformationAction Continue
} | Receive-Job -Wait -AutoRemoveJob -InformationAction Continue
} | Receive-Job -Wait -AutoRemoveJob -InformationAction Continue
} | Receive-Job -Wait -AutoRemoveJob -InformationAction Continue
} | Receive-Job -Wait -AutoRemoveJob -InformationAction Continue

Also, it is not jobs specific. It is how PowerShell remoting work in general:

Invoke-Command . {
Invoke-Command . {
Invoke-Command . {
Invoke-Command . {
Invoke-Command . {
    Write-Information Test -InformationAction Continue
} -EnableNetworkAccess -InformationAction Continue
} -EnableNetworkAccess -InformationAction Continue
} -EnableNetworkAccess -InformationAction Continue
} -EnableNetworkAccess -InformationAction Continue
} -EnableNetworkAccess -InformationAction Continue

[iSazonov]

It is how PowerShell remoting work in general:

It seems this is in serialization code.

[PetSerAl]

@iSazonov I do not see how it is related with serialization. Here:
https://github.com/PowerShell/PowerShell/blob/bd5f7719bce3579f8128b498c8d059f6a0daf528/src/System.Management.Automation/engine/MshCommandRuntime.cs#L753
it pass InformationRecord along. And here:
https://github.com/PowerShell/PowerShell/blob/bd5f7719bce3579f8128b498c8d059f6a0daf528/src/System.Management.Automation/engine/MshCommandRuntime.cs#L819
it also write message on host. So, each time InformationRecord processed it also generate additional message on host (assuming the conditions:
https://github.com/PowerShell/PowerShell/blob/bd5f7719bce3579f8128b498c8d059f6a0daf528/src/System.Management.Automation/engine/MshCommandRuntime.cs#L755-L756
are met).

[iSazonov]

@PetSerAl I don't remeber details. I tried optimize streams and I rested on remoting and serialization and had to postpone the work (to preserve backword compatibility).

[Jaykul]

This is a major pain.

Receive-Job and Invoke-Command respect the $InformationPreference from the calling scope which means that any script or function that receives a job (possibly including the upcoming foreach -parallel which is not explicitly using jobs) is going to get double output from any Write-Host -- and also from any Write-Information where the $InformationPreference is "Continue" _inside_ the job.

We tried using the Information stream on some new code last week and ended up with doubled output all over the place, and _wasted hours tracking down the double output_ to the fact that we'd passed in the InformationPreference in some remoting code because we wanted the information to be output to host (for logging) on the remote machine, but the script that's calling it _also_ has it's preference set to Continue for the same reason...

[kilasuit]

In PowerShell v5 Write-host was changed to also output to the Information stream as per https://docs.microsoft.com/en-us/powershell/module/microsoft.powershell.utility/write-host?view=powershell-6

Write-Host (Microsoft.PowerShell.Utility)

The Write-Host cmdlet customizes output. You can specify the color of text by using the ForegroundColor parameter, and you can specify the background color by using the BackgroundColor parameter. The Separator parameter lets you specify a string to use to separate displayed objects. The particular result depends on the program that is hosting PowerShell. Note Starting in Windows PowerShell 5.0, Write-Host is a wrapper for Write-Information This allows you to use Write-Host to emit output to the information stream. This enables the capture or suppression of data written using Write-Host while preserving backwards compatibility. The $InformationPreference preference variable and InformationAction common parameter do not affect Write-Host messages. The exception to this rule is -InformationAction Ignore, which effectively suppresses Write-Host output. (see "Example 5")

So I think this is as expected.

[mklement0]

@kilasuit: That Write-Host writes to the information stream is indeed expected; that the information is _duplicated_, as described in the OP, is not.

For the full extent of the problem, which affects all streams other than success and error, see #9585