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

Start/Stop-Transcript does not capture everything written to the console #10994

Open
zammitt opened this issue Nov 5, 2019 · 26 comments
Open
Labels
Committee-Reviewed PS-Committee has reviewed this and made a decision Issue-Enhancement the issue is more of a feature request than a bug WG-Cmdlets general cmdlet issues

Comments

@zammitt
Copy link

zammitt commented Nov 5, 2019

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
@zammitt zammitt added the Issue-Question ideally support can be provided via other mechanisms, but sometimes folks do open an issue to get a label Nov 5, 2019
@JamesWTruher JamesWTruher added the Review - Committee The PR/Issue needs a review from the PowerShell Committee label Nov 6, 2019
@JamesWTruher
Copy link
Member

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

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

he852100 commented Nov 7, 2019

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

@zammitt
Copy link
Author

zammitt commented Nov 8, 2019

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

vexx32 commented Nov 8, 2019

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

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

@SteveL-MSFT SteveL-MSFT added Committee-Reviewed PS-Committee has reviewed this and made a decision and removed Review - Committee The PR/Issue needs a review from the PowerShell Committee labels Jan 8, 2020
@iSazonov iSazonov added Up-for-Grabs Up-for-grabs issues are not high priorities, and may be opportunities for external contributors Issue-Enhancement the issue is more of a feature request than a bug and removed Issue-Question ideally support can be provided via other mechanisms, but sometimes folks do open an issue to get a labels Jan 31, 2020
@Cloudmersive
Copy link

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

mklement0 commented Mar 7, 2020

To complete the picture of the current problems and limitations:

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

@sba923
Copy link
Contributor

sba923 commented Dec 4, 2020

Just discovered that Start-Transcript typically captures little to no output from ROBOCOPY.

image

image

image

PSTranscriptAndRobocopy.zip

Would there be a workaround?

@mklement0
Copy link
Contributor

I see the problem in 7.1.0 (as you do), and also still in in 7.2.0-preview.1.

Appending | Out-Host is a workaround for PS Core (none needed for WinPS), though the formatting is a bit off.

@aolszowka
Copy link

This also does not work for WhatIf if ran in an Invoke-Command; See #9870 (comment)

@kilasuit
Copy link
Collaborator

I was playing with .Net Interactive notebooks & looking into this for why this issue with Notebooks occurs dotnet/interactive#1430 as this is a crucial item that needs fixed before I can recommend to Jupyter Notebooks using .Net Interactive to users in production environments that will have org wide transcription enforced, & I would like to be able to recommend using them without needing to resort to a non-workable workaround cc @SteveL-MSFT

@Zeal0us
Copy link

Zeal0us commented Nov 9, 2021

This is pretty disappointing, it's one of those things you expect to just work when you find it, and then you check your log file and it's got 20 lines out of tens of thousands.

@TheOnlyWei
Copy link

TheOnlyWei commented Apr 6, 2022

Similar problem when you try to run PowerShell 7 code with Start-Transcript from a PowerShell 5 session (not sure if that is the same exact issue as this). You see the output in PowerShell 5 console, but when you check the log file that Start-Transcript output to, it is missing a lot of the output. The same work-around, involving appending | Out-Host to parts of code where the output is not showing in the transcript, works. I didn't want to capture transcript from PowerShell 5 as it outputs weird symbols and interprets regular output as errors from different applications.

@Cistalvo
Copy link

Cistalvo commented Jun 3, 2022

Any dev update on this? I might have stumbled over this error, just wondering if it was fixed in the meantime.

@buscseik
Copy link

This issue still exists and it is worse than ever. It was not good in PS5 but in PS7 even worse.
Start-transcript can't literally be used

This is a crutial feature. Please fix it. This issue started before 2015.
PowerShell is great, Windows Terminal is great, but due this I will have to switch some third party solution like Moba Xterm which actually can log everthing without any issue.

@johnbailey-transactcampus

@SteveL-MSFT - This issue is still prevalent. I can reproduce the Start-Transcript issue if the Invoke-RestMethod commandlet is called with a POST method.

In my case, the workaround of utilising | Out-Host (mentioned above) on PS 7.2.5 still does not produce any viable command invocation output (for monitoring/auditing) - whether the command succeeds or fails:

**********************
Command start time: 20220722090610
**********************
PS>TerminatingError(Invoke-RestMethod): "{ "statusCode": 401, "message": "Unauthorized. Access token is missing or invalid." }"

If I append -Verbose and -Debug on the Invoke-RestMethod command, then I lose the Invocation Header data (e.g.: Command start time:) from the transcript for the command - which makes it even harder to determine the details of the command that was run (when a failure doesn't occur):

VERBOSE: DELETE with 0-byte payload
VERBOSE: received 85-byte response of content type application/json
>> TerminatingError(Invoke-RestMethod): "{ "statusCode": 401, "message": "Unauthorized. Access token is missing or invalid." }"

As it appears that there hasn't been any traction on this - for quite some time - is it possible to help the community derive a work-around for the[se] issue[s], until it[they] can be addressed in the code-base?

@SteveL-MSFT
Copy link
Member

I hope people understand that if this was easy to fix, we would have done it. The transcription code is more than 10 years old and its design has limitations not easily addressed. The robocopy example above is an example where the NativeCommandProcessor has an optimization where if a native command is at the end of the pipeline, then it doesn't read the stdout pipe and instead just has the exe send the output directly to the console. In this case, transcription is not aware (since PowerShell is not aware) of any output. Piping to a cmdlet works around this optimization.

It would actually be easier to create a script-like executable (perhaps called transcript.exe that does what script does which is start a new instance of the shell that ran it and read stdout/stderr/stdin and write that to a file while also passing it through to the shell. Doing it within the shell is problematic due to output being "leaky".

@psawa
Copy link

psawa commented Aug 5, 2022

Then what's the point of this command if the transcription cannot be relied on? This is just an extreme flaw for a crucial and basic cmdlet

@SteveL-MSFT SteveL-MSFT added WG-Cmdlets general cmdlet issues and removed Up-for-Grabs Up-for-grabs issues are not high priorities, and may be opportunities for external contributors labels Aug 8, 2022
@Xechorizo
Copy link

Xechorizo commented Oct 5, 2022

if this was easy to fix, we would have done it

If it weren't vital functionality, why would the community want it? Your team only fixes easy problems?

If it can't be done, remove it (or note it as an experimental, deprecated, or otherwise unreliable cmdlet)

@sba923
Copy link
Contributor

sba923 commented Oct 5, 2022

If it can't be done, remove it.

I'd rather have PowerShell with limited transcript functionality than with none at all.

@nzbart
Copy link

nzbart commented Nov 1, 2022

While I agree that Start-Transcript is fairly useless due to this problem and not capturing the output from executables, if anyone has a workaround for this problem, please post it here. A suitable workaround could include something like:

  1. A new function such as recommended here: Start/Stop-Transcript does not capture everything written to the console #10994 (comment); or
  2. A new host process that can "tee" the output to file.

@SteveL-MSFT currently, the documentation for Start-Transcript says:

The transcript includes all command that the user types and all output that appears on the console.

Would it be possible to at least list the limitations of the current command, such as not capturing the output from executables in the documentation to save people a lot of time wondering why it's not working as documented?

@Bibench-R7
Copy link

Bibench-R7 commented Nov 10, 2022

It does capture executable output, but only 10 lines or so on hundreds. Since it looked like it worked for a few lines of test, I discovered after the fact that all my logs are worthless.

@SyntevoAlex
Copy link

My understanding of the issue is that this is a race. If PowerShell doesn't "flush" output before Stop-Transcript is executed, the output gets lost. In my scripts, I think I'm seeing that sometimes output lands, and sometimes it's lost.

Regarding workarounds: is it possible to force PowerShell to flush? I would just do it before Stop-Transcript, problem solved?

@aetonsi
Copy link

aetonsi commented Mar 31, 2023

Ok i just discovered the reason why the transcript for choco list -localonly -all saves literally 9 out of 151 lines of output....

And it saves absolutely nothing if i pipe to grep (choco list -localonly -all | grep -i a)

@aetonsi
Copy link

aetonsi commented Mar 31, 2023

My understanding of the issue is that this is a race. If PowerShell doesn't "flush" output before Stop-Transcript is executed, the output gets lost. In my scripts, I think I'm seeing that sometimes output lands, and sometimes it's lost.

Regarding workarounds: is it possible to force PowerShell to flush? I would just do it before Stop-Transcript, problem solved?

Mmh that's not a bad idea, if that is really the culprit.. so far i tried the following but it didn't do anything, maybe someone knows something more?

PS>[console]::OpenStandardOutput().Flush()
PS>[console]::OpenStandardError().Flush()
PS>[console]::Out.Flush()
PS>[console]::Error.Flush()

@sba923
Copy link
Contributor

sba923 commented Sep 29, 2023

Yesterday found out that Start-Transcript also does not capture the output from VScode command-line operations such as code --install-extension foo. One more case that makes it essentially useless...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Committee-Reviewed PS-Committee has reviewed this and made a decision Issue-Enhancement the issue is more of a feature request than a bug WG-Cmdlets general cmdlet issues
Projects
None yet
Development

No branches or pull requests