Powershell: Inconsistent Start-Transcript behavior with respect to the error and information streams

[mklement0]

I'm making the following assumptions about how Start-Transcript is designed to work (can't tell from the documentation):

• Whatever streams are neither captured nor redirected are transcribed, and preference variables with respect to which Write-* cmdlets should actually produce output are honored; another way of putting it: Whatever output displays in the console, across all streams, is also what should get transcribed.

Currently, Start-Transcript doesn't always work that way:

• Even with *>$null applied to a script that uses Start-Transcript, which should keep _all_ streams out of the transcript, _errors_ (stream 2) and Write-Host output (stream 6) are still transcribed.

  • You can _partially_ keep error output out of the transcript If you use $ErrorActionPreference = 'SilentlyContinue': outside of a transcript that would silence _all_ errors (non-terminating, statement-terminating, script-terminating - albeit the latter two against documented behavior), but in a transcript _cmdlet-triggered_ statement-terminating errors are unexpectedly still transcribed.

  • Errors that do get transcribed are transcribed twice by default.

  • _Cmdlet-triggered_ statement-terminating errors are preceded by an _extra line_ repeating the error message, with a prefix such as >>TerminatingError(<command>): <message>
    It is this line that shows in the transcript even with $ErrorActionPreference = 'SilentlyContinue' in effect.

  • Unlike outside of a transcript, with $ErrorActionPreference at its default, $Continue:

    • a _cmdlet-triggered_ statement-terminating error acts like a _script_-terminating one.
    • a script-terminating error prints neither to the console nor records the error in the transcript.
    • the transcript is _aborted_ in both cases, however.

• Even though Write-Information output (stream 6) is by default _not_ printed to the console $InformationAction is 'SilentlyContinue' by default), it is still transcribed. [_Update_: This appears to have been fixed, but I don't know where and when (the problem persists in _Windows PowerShell_)]

Steps to reproduce

Create script t.ps1 with the following content:

$null = Start-Transcript t.log

write-warning 'warn'
write-verbose 'verbose'

write-information 'info'
write-host 'host'

write-output 'data'

# Generate a non-terminating error
Write-Error 'error'

# Generate an expression-based statement-terminating error.
1/0

# Generate a cmdlet-based statement-terminating error.
Get-Item -NoSuchParam

$null = Stop-Transcript

Then run the following commands, one after the other:

A)

./t.ps1

B)

./t.ps1 *>$null

C)

& { $ErrorActionPreference = 'SilentlyContinue'; ./t.ps1 }

Expected behavior

Inspect output file t.log:

A)
Coloring aside, whatever printed to the console should appear in the transcript (sandwiched between a header and a footer).

B)
Except for the header and footer, the transcript should be empty (all streams were suppressed).

C)
No errors of any kind should be transcribed.

Actual behavior

A)

• INFO: info shows in the transcript, even though it doesn't show in the console (with $InformationPreference at its default value, SilentlyContinue).
  As an aside: Non-suppressed Write-Information output in the _console_ has _no_ INFO: prefix , but does in the _transcript_ (whereas Write-Warning, Write-Verbose and Write-Debug print a prefix in _both_ scenarios).

[_Update_: This appears to have been fixed, but I don't know where and when (the problem persists in _Windows PowerShell_)]

• All errors show _twice_ in the transcript.
  
  
  
  • The _first_ instance of the cmdlet-triggered statement-terminating error is preceded by an extra line duplicating the regular error representation:
    
    >> TerminatingError(Get-Item): "A parameter cannot be found that matches parameter name 'NoSuchParam'."
  
  

B)

• host (Write-Host output) still shows in the transcript.

• All errors still show in the transcript (now only _once_).

C)

While the non-terminating error and the expression-triggered error were successfully suppressed, the _cmdlet-triggered_ _terminating_ error still shows in the transcript, but only by the extra line:
PS>TerminatingError(Get-Item): "A parameter cannot be found that matches parameter name 'NoSuchParam'."

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)

[nowakca]

I've found that if I get a 404 from an Invoke-WebRequest inside a Try/Catch handler (which catches the error and provides no output, squelching it), I don't see anything on screen (which is as it should be), but I do see a "TerminatingError(Invoke-WebRequest)" and response content in the Transcript (which should not be)

[rkeithhill]

OK this is a bit evil IMO. Enabling transcription should not fundamentally change the behavior of the script. I ran into this last Friday and took me a while to figure out this transcription bug was biting me. Here's my simple repro on a Linux machine using GNU make. There are two files (put in the same dir). Here is my simplified makefile:

# make wants tabs insteads of spaces so when copying this, replace the four spaces before 
# the warning message with a single tab.
foo:
    $(warning SOME WARNING TEXT)

And here is my test.ps1 file - be sure to chmod +x ./test.ps1 to make it executable:

#!/usr/bin/env pwsh

$ErrorActionPreference = "Stop"
$Transcribe = 0

if ($Transcribe) { Start-Transcript test.log }

try {
    make -f makefile foo
    if ($LASTEXITCODE) { throw "make failed with $LASTEXITCODE" }

    "should get here - we do without transcription"
}
catch {
    "should not get here"
    throw $_
}
finally {
    if ($Transcribe) { Stop-Transcript }
}

With the above settings, I can execute this script and it works as I expect it to:

makefile:4: SOME WARNING TEXT
make: 'foo' is up to date.
should get here - we do without transcription

Now set the $Transcribe variable to 1 and re-run the script. Just enabling transcription causes the script to crash now (the error handling behavior has fundamentally changed):

Transcript started, output file is test.log
make: 'foo' is up to date.
should not get here
Transcript stopped, output file is /home/hillr/pwsh-bug/test.log

BTW this issue does not crop up on Windows - adding to its "evilness".