Powershell: Start/Stop-Transcript does not capture everything written to the console

[zammitt]

Start/Stop-Transcript does not always capture everything written to the console.

I created a github repo with code, repro steps and more context: https://github.com/zammitt/PowerShellTranscriptIssue

Steps to reproduce

In a script file (.ps1)
1) Start-Transcript
2) Run a Cmdlet that outputs data with WriteObject
3) Stop-Transcript
4) Observe that the output was not written to the transcript

Here is a script to repro:

Install-Module TranscriptIssue
Import-Module TranscriptIssue

Start-Transcript -Path transcript.txt -UseMinimalHeader

Write-Output "Hello from Write-Output"
Write-Host "Hello from Write-Host"

Test-TranscriptIssue

Write-Output "Goodbye from Write-Output"
Write-Host "Goodbye from Write-Host"

Stop-Transcript

# Write out the transcript to the console
cat ./transcript.txt

The code for Test-TranscriptIssue can be found here: https://github.com/zammitt/PowerShellTranscriptIssue/blob/master/TestIssueOnPowerShellCore/Test-TranscriptIssue.cs

Expected behavior

The contents of the transcript match what was written to the console while the transcript was active.

Transcript started, output file is transcript.txt
Hello from Write-Output
Hello from Write-Host

Goodbye from Write-Host
TestProperty
------------
TestValue
Goodbye from Write-Output
Transcript stopped, output file is D:\code\PowerShellTranscriptIssue\TestIssueOnPowerShellCore\bin\Debug\netcoreapp3.0\transcript.txt
**********************
PowerShell transcript start
Start time: 20191105180138
**********************
Hello from Write-Output
Hello from Write-Host

Goodbye from Write-Host
TestProperty
------------
TestValue
Goodbye from Write-Output
**********************
PowerShell transcript end
End time: 20191105180138
**********************

Actual behavior

The transcript is missing data that was written to the console while the transcript was active.

Transcript started, output file is transcript.txt
Hello from Write-Output
Hello from Write-Host

Goodbye from Write-Host
TestProperty
------------
TestValue
Goodbye from Write-Output
Transcript stopped, output file is D:\code\PowerShellTranscriptIssue\TestIssueOnPowerShellCore\bin\Debug\netcoreapp3.0\transcript.txt
**********************
PowerShell transcript start
Start time: 20191105180138
**********************
Transcript started, output file is transcript.txt
Hello from Write-Output
Hello from Write-Host

Goodbye from Write-Host
**********************
PowerShell transcript end
End time: 20191105180138
**********************

Environment data

Name                           Value
----                           -----
PSVersion                      6.2.3
PSEdition                      Core
GitCommitId                    6.2.3
OS                             Microsoft Windows 10.0.17134
Platform                       Win32NT
PSCompatibleVersions           {1.0, 2.0, 3.0, 4.0…}
PSRemotingProtocolVersion      2.3
SerializationVersion           1.1.0.1
WSManStackVersion              3.0

[JamesWTruher]

TLDR:

• Mixing and matching objects, strings, and write-host with transcription is _really_ tricky.

I’m not sure this is a bug, per se, but a subtle interaction between the script and how transcription works with our pipelines. I will agree that it is in no way intuitive.

One of the things that happen when you emit objects is that the formatting of those objects gets handled by out-default, but after the script has completed and since transcription has stopped, that output doesn’t get transcribed. Strings are handled differently, they’re sometimes short-circuited through formatting (but sometimes not). The combination of write-host (which makes an immediate write), write-object (which may get short-circuited through formatting), and output of a makes this pretty hard to reason about what’s going to happen. However, there may be a way that you may want to try (See “A POSSIBLE WAY” below).

Even more details:

Here are a couple of variations on the theme:

Variation 1 – your scenario, with the output of a structured object at the end of all of the other operations.

PS> cat s2.ps1
remove-item s2 -ea ignore
start-transcript s2 -usemin
write-host "1"
write-output "2"
get-location
write-host "4"
write-output "5"
stop-transcript

PS> ./s2.ps1
Transcript started, output file is s2
1
2

4
Path
----
/Users/jimtru/src/projects/transcript
5
Transcript stopped, output file is /Users/jimtru/src/projects/transcript/s2
 ```

This one is really confusing, but explainable (but perhaps not satisfying). ‘Write-Host 4’ is visible before `get-location` because Write-Host is hot-rodded directly into the host and emitted (there’s code in transcription which essentially tees the output to the transcript file and the console). Then we have the regular output of `get-location` and `write-output 5` sent as output of the script.

Since transcription is turned off before the script exits, it’s not rendered in the transcript, because the objects were sent to the next consumer in the pipeline (in this case, it’s out-default which is what the engine does automatically). The tricky bit is that strings are also somewhat hot-rodded in our formatting, so the first `write-output 2` gets emitted and captured by the transcript, but the insertion of the `get-location` object causes it to be pushed into the stack of things that need actual formatting, which sets a bit of state for any remaining objects which may need formatting (which is why the second `write-output 5` doesn’t get transcripted.

 ```powershell
**********************
PowerShell transcript start
Start time: 20191106114858
**********************
Transcript started, output file is s2
1
2

4
**********************
PowerShell transcript end
End time: 20191106114858
**********************
 ```

Variation 2 – move the object emission to the beginning

```powershell 
start-transcript s3 -usemin
get-location
write-host "1"
write-output "2"
write-host "4"
write-output "5"
stop-transcript

We can see that the write-host happen before anything, and then the objects start to come out. The string output essentially forces the object to be rendered to the screen, but you’ll notice that the transcript contains only the output of Write-Host. That’s because those were piped to the formatting after the script turned off transcription.

PS> ./s3.ps1
Transcript started, output file is s3

1
4
Path
----
/Users/jimtru/src/projects/transcript
2
5
Transcript stopped, output file is /Users/jimtru/src/projects/transcript/s3


PS> cat s3

**********************
PowerShell transcript start
Start time: 20191106115142
**********************
Transcript started, output file is s3

1
4
**********************
PowerShell transcript end
End time: 20191106115142
**********************

Variation 3 – object emission at the end:
We can see that everything but the object is now in the transcript

PS> cat s4.ps1
start-transcript s4 -usemin
write-host "1"
write-output "2"
write-host "4"
write-output "5"
get-location
stop-transcript

Here’s the execution flow

PS> ./s4.ps1
Transcript started, output file is s4
1
2
4
5

Path
----
/Users/jimtru/src/projects/transcript
Transcript stopped, output file is /Users/jimtru/src/projects/transcript/s4

And the content of the transcript

**********************
PowerShell transcript start
Start time: 20191106115255
**********************
Transcript started, output file is s4
1
2
4
5

**********************
PowerShell transcript end
End time: 20191106115255
**********************

A Possible Way

Lastly, here’s a slight variation on the original, but now everything will be in the transcript. I’ve taken the code of interest and am calling the formatter forcefully via out-default. You’ll notice that the last Write-Host call is still out of order, that’s because of the short-circuiting of write-host which is a direct call into the host and does not go into the output stream.

start-transcript s5 -usemin
.{
    write-host "1"
    write-output "2"
    get-location
    write-host "4"
    write-output "5"
} | out-default
stop-transcript

Here’s the execution, followed by the transcript

PS> ./s5.ps1
Transcript started, output file is s5
1
2

4
Path
----
/Users/jimtru/src/projects/transcript
5

Transcript stopped, output file is /Users/jimtru/src/projects/transcript/s5


PS> cat s5
**********************
PowerShell transcript start
Start time: 20191106115701
**********************
Transcript started, output file is s5
1
2

4
Path
----
/Users/jimtru/src/projects/transcript
5

**********************
PowerShell transcript end
End time: 20191106115701
**********************

[he852100]

I suggest adding a new option. Allows it to output color documents

[zammitt]

@JamesWTruher Thank you for the detailed reply. Out-Default works great! I ended up using the -Transcript flag so that the objects are still passed forward on the pipeline.

@he852100 I'll second this. Color in transcripts would be awesome.

[vexx32]

My one question to that is always going to be -- how? PS works with text files, not formatted documents. The next step up would perhaps be Markdown, which would be messier to read in the console, and still doesn't natively support color formatting. That should probably be a whole other issue discussion, though. 😉

[SteveL-MSFT]

@PowerShell/powershell-committee reviewed this, we believe a complete solution for transcription (like the unix script command) would love to see the community build a new cmdlet (published to PSGallery) that uses ptty or on Windows grabbing the screen buffer, but the ask is out of scope for the current transcription framework.

[Cloudmersive]

Dear Microsoft - when are you going to fix this? @SteveL-MSFT this is critical functionality - how is it "out of scope"? It is critically important that bedrock Microsoft capabilities actually solve problems at scale and this is a huge gap

[mklement0]

To complete the picture of the current problems and limitations:

• Interactive prompts are never transcribed - unlike with the Unix script utility, you neither see the prompt string nor what the user typed.

• 4645 describes duplicated output in transcripts and situationally _changed behavior_ when transcript ion is used.

• As for the Out-Default workaround for the issue at hand:

  • Given that we shouldn't promote use of Out-Default in user code, Out-Host is the better choice, but it is still a flawed workaround:

    • You lose the ability to capture any output from the script.
    • Due to #11134, stderr output from _external programs_ will be missing from the transcript.

On Unix-like platforms, use of the script utility already is an option to bypass all these issues (albeit not from _within_ a script), while additionally providing:

• capturing of VT sequences (ANSI escapes)
• capturing of interactive prompt strings and _what the user typed_

However, the PSReadLine module doesn't play nice with the latter in Read-Host calls; e.g. (on Linux):

# Transcribe an interactive PowerShell user prompt.
# Save the transcript in file .\typescript
script -c 'pwsh -nop -c "read-host prompt"'

If you type abc when prompted, the transcript won't contain just string abc, but the equivalent following, which makes the terminal go haywire when you cat the resulting file; note how each letter typed caused the inclusion of VT sequences and reprinting of all letters typed so far:

`e[?1h`e=prompt:·`e[6na`e[62;9Hab`e[62;9Habc