Out-Default incorrectly staying in transcript state #3392

SteveL-MSFT · 2017-03-21T23:30:03Z

Out-Default was incorrectly caching transcription state as the subsequent use was caching the already changed state

Out-Default needed to implement IDispose pattern so transcription state reverts back on exception in pipeline

Addresses #3390

PetSerAl

It ends up Out-Default -Transcript just set TranscribeOnly = true on start (BeginProcessing) and TranscribeOnly = false on end (Dispose).

PetSerAl · 2017-03-22T00:17:18Z

src/System.Management.Automation/commands/utility/FormatAndOutput/out-console/OutConsole.cs

You ends up restoring TranscribeOnly even if you not capture it before.

PetSerAl · 2017-03-22T00:21:25Z

src/System.Management.Automation/commands/utility/FormatAndOutput/out-console/OutConsole.cs

You never set _transcriptStateChanged back to false. So Out-Default stop capturing TranscribeOnly after first call with -Transcript switch.

Out-Default lifetime only exists in that pipeline and typically should be the last thing in the pipeline as nothing is emitted if used with -Transcript. Is there a case that's broken?

I am not going to say that nested or intersected Out-Default -Transcript are useful scenario, but if you are not support it, then (taking in account that OutDefaultCommand is the only place where TranscribeOnly modified) the only value that _savedTranscribeOnly will have is false. So, why bother and define variable, which will be always false?

PetSerAl · 2017-03-22T19:29:58Z

src/System.Management.Automation/commands/utility/FormatAndOutput/out-console/OutConsole.cs

You define _transcriptStateChanged as static, so it affect entire AppDomain. That might be not good when multiple PowerShell Runspaces share same AppDomain.

& { [PowerShell]::Create().AddCommand('Out-Default').AddParameter('Transcript').Invoke() } | Out-Default -Transcript

SteveL-MSFT · 2017-03-23T19:42:55Z

@PetSerAl I appreciate the feedback. I rethought about how BeginProcessing, ProcessRecord, and EndProcessing work and I think I have a solution that remedies your concerns

lzybkr · 2017-03-23T22:03:18Z

src/System.Management.Automation/commands/utility/FormatAndOutput/out-console/OutConsole.cs

Just asking - but should TranscribeOnly be a counter that is incremented each time it's true, and decremented in Dispose?

I'm not sure this is the correct semantic, but it seems right - like it shouldn't be possible to turn it off as long as somebody wants it on.

I only learned that Out-Default had a -Transcript switch when this issues was opened and I started looking into it (documentation and tests are also lacking).

Best as I can tell, although you can have nested Start-Transcript, Out-Default is only used at the end of a pipeline, so the test case of Out-Default -Transcript | Out-Default -Transcript I don't think represents a real use case as the intent of -Transcript (as far as I can tell) is to suppress output to the pipeline and only send it to the transcript. However, it got the console stuck in transcript mode, so I thought it was worth fixing (the other issue with exception being raised is a real use case).

So I don't think we need a counter here as it should really just toggle from true and false when this cmdlet is used.

as the intent of -Transcript (as far as I can tell) is to suppress output to the pipeline

Sadly it is exact opposite of how Out-Default -Transcript is implemented. By default Out-Default does not output anything, but display input on host. With -Transcript it pass thru the input, but making following Out-Default/Out-Host to not display their input:

1..10 | Out-Default -Transcript | Out-Host

But by replacing Out-Host with Write-Host you can see, that output is really here:

1..10 | Out-Default -Transcript | Write-Host

Looking at the code, the only thing TranscribeOnly does is not write to the console so I mispoke when I said pipeline (should have said host).

PetSerAl · 2017-03-24T02:30:10Z

@SteveL-MSFT I can not think of any problematic cases now, at least Out-Default that PowerShell console host implicitly adds to the pipeline will restore TranscribeOnly to false at the end of command.

PetSerAl · 2017-03-24T02:33:58Z

src/System.Management.Automation/commands/utility/FormatAndOutput/out-console/OutConsole.cs

Do you really need explicitly state IDisposable here? FrontEndCommandBase already implement IDisposable and it is not like you need to reimplement IDisposable.Dispose() here.

That was a leftover from before I realized FrontEndCommandBase implements IDisposable. Will remove.

PetSerAl · 2017-03-24T02:35:35Z

src/System.Management.Automation/commands/utility/FormatAndOutput/out-console/OutConsole.cs

Are not you supposed to call base.InternalDispose() at some point of overriding method?

You're correct. Will fix.

…uent use was caching the already changed state Out-Default needed to implement IDispose pattern so transcription state reverts back on exception in pipeline

addressed feedback from code review on using static

added missing call to base.InternalDispose()

SteveL-MSFT · 2017-03-24T22:44:09Z

@PetSerAl @lzybkr any other feedback preventing signoff?

PetSerAl · 2017-03-25T06:49:04Z

@SteveL-MSFT I do not see any obvious wrong things. I still can construct the case where host stuck in TranscribeOnly state, but it looks more likely shooting your own leg:

begin{
    $sp = {Out-Default -Transcript}.GetSteppablePipeline()
    $sp.Begin($false)
    $sp.Process()
}
end{
    $sp.End()
    $sp.Dispose()
}

Possible, the only way to prevent this is to implement TranscribeOnly as counter as @lzybkr suggest.
Maybe you should take into account possibility, that cmdlet can be instantiated not for execution, but for parameter/argument completion (not sure if it is the case here as Out-Default does not implement dynamic parameters). In that case BeginProcessing will not be invoked before disposing, so you will end restoring TranscribeOnly when you are not save it.

SteveL-MSFT · 2017-03-25T18:26:09Z

I'll rework it to use a counter. Thanks.

PetSerAl · 2017-03-25T23:00:01Z

src/System.Management.Automation/commands/utility/FormatAndOutput/out-console/OutConsole.cs

You are doing this in process block, once for each input item, not once per Out-Default invocation.

Moving back to BeginProcessing()

PetSerAl · 2017-03-25T23:00:03Z

src/System.Management.Automation/commands/utility/FormatAndOutput/out-console/OutConsole.cs

You are not checking if you actually increment TranscribeOnlyCount before. That lead to situation where every call to Out-Default reduce counter. Including ones without -Transcript. Or where begin block of Out-Default does not have opportunity to execute:

& {begin{throw}} | Out-Default -Transcript

PetSerAl · 2017-03-26T00:34:54Z

src/System.Management.Automation/commands/utility/FormatAndOutput/out-console/OutConsole.cs

Maybe wrap this with try/finally, so you have opportunity to clean up even if base.InternalDispose() throw exception.

Sounds good

… -Trascript stays in TranscibeOnly Add try..finally in InternalDispose to ensure TranscribeOnlyCount gets decremented

PetSerAl · 2017-03-26T11:49:53Z

To think about that. Should not it also properly revert TranscribeOnly even if Dispose is not called, but Out-Default collected by garbage collector?

$sp = {Out-Default -Transcript}.GetSteppablePipeline()
$sp.Begin($false)
$sp = $null
[GC]::Collect()

I have idea about implementation. Can you look at it?

SteveL-MSFT · 2017-03-27T16:02:24Z

@PetSerAl I'll look at this today

SteveL-MSFT · 2017-03-27T17:06:40Z

@PetSerAl I stepped through the debugger and BeginProcessing is always called and ProcessRecord is called where InputObject is empty. Finally, Dispose() is called. In both your samples, once the script is complete, Host.UI.TranscribeOnlyCount = 0.

PetSerAl · 2017-03-27T17:56:03Z

@SteveL-MSFT Not sure, what exact code you are referencing as my samples, but I use following code for test:

PS> Add-Type @‘
>>>     using System;
>>>     using System.Management.Automation;
>>>     [Cmdlet("Test", "Methods")]
>>>     public class TestMethods : PSCmdlet, IDisposable {
>>>         public TestMethods() {
>>>             Console.WriteLine("Constructor");
>>>         }
>>>         ~TestMethods() {
>>>             Console.WriteLine("Destructor");
>>>         }
>>>         protected override void BeginProcessing() {
>>>             Console.WriteLine("Begin");
>>>         }
>>>         protected override void ProcessRecord() {
>>>             Console.WriteLine("Process");
>>>         }
>>>         protected override void EndProcessing() {
>>>             Console.WriteLine("End");
>>>         }
>>>         protected override void StopProcessing() {
>>>             Console.WriteLine("Stop");
>>>         }
>>>         public void Dispose() {
>>>             Console.WriteLine("Dispose");
>>>         }
>>>     }
>>> ’@ -PassThru | Select-Object -First 1 -ExpandProperty Assembly | Import-Module
PS> $sp = {Test-Methods}.GetSteppablePipeline();
Constructor
PS> $sp.Begin($false)
Begin
PS> $sp = $null
PS> [GC]::Collect()
Destructor
PS>

As you can see, Dispose is not called here.

SteveL-MSFT · 2017-03-27T18:03:02Z

@PetSerAl, by samples, I mean:

begin{
    $sp = {Out-Default -Transcript}.GetSteppablePipeline()
    $sp.Begin($false)
    $sp.Process()
}
end{
    $sp.End()
    $sp.Dispose()
}

and

$sp = {Out-Default -Transcript}.GetSteppablePipeline()
$sp.Begin($false)
$sp = $null
[GC]::Collect()

In both of these cases, the Out-Default cmdlet's Begin/Process/Dispose are called (where -Transcript is passed). I was trying to incorporate both of these as Pester tests, but didn't observe the expected failing behavior.

PetSerAl · 2017-03-27T18:35:34Z

@SteveL-MSFT The first sample got fixed, when you implement TranscribeOnly as a counter. But second one is still lock console in transcribe only mode, when I test in on this commit:

PS> $sp = {Out-Default -Transcript}.GetSteppablePipeline()
PS> $sp.Begin($false)
PS> $sp = $null
PS> [GC]::Collect()
PS> 1..10
PS> [System.Management.Automation.Host.PSHostUserInterface].GetProperty('TranscribeOnlyCount', [System.Reflection.BindingFlags]'Instance, NonPublic').GetValue($Host.UI) | Write-Host
1
PS>

SteveL-MSFT · 2017-03-27T20:35:18Z

@PetSerAl your proposed change looks good to me, can you submit that as a PR and include the tests I added to this PR? I'll close this one

PetSerAl · 2017-03-27T20:54:35Z

@SteveL-MSFT OK. I can do that.

SteveL-MSFT · 2017-03-27T21:26:29Z

@PetSerAl thanks for your help on this

SteveL-MSFT assigned TravisEz13 Mar 21, 2017

SteveL-MSFT requested a review from anmenaga March 21, 2017 23:30

msftclas added the cla-not-required label Mar 21, 2017

PetSerAl reviewed Mar 22, 2017

View reviewed changes

iSazonov added the Review - Waiting on Author label Mar 23, 2017

lzybkr reviewed Mar 23, 2017

View reviewed changes

SteveL-MSFT removed the Review - Waiting on Author label Mar 23, 2017

PetSerAl reviewed Mar 24, 2017

View reviewed changes

SteveL-MSFT added 4 commits March 23, 2017 19:55

Out-Default was incorrectly caching transcription state as the subseq…

f9dd4f7

…uent use was caching the already changed state Out-Default needed to implement IDispose pattern so transcription state reverts back on exception in pipeline

only restore Host.UI.TranscribeOnly if state had changed

74d92eb

added addtional test for normal use case for out-default -transcript

0ae56b6

addressed feedback from code review on using static

removed unnecessary IDisposable as FrontEndCommandBase already inherits

e3c05ed

added missing call to base.InternalDispose()

SteveL-MSFT force-pushed the outdefault branch from 0b9973c to e3c05ed Compare March 24, 2017 03:07

PetSerAl reviewed Mar 25, 2017

View reviewed changes

SteveL-MSFT force-pushed the outdefault branch from b9f25eb to 6dd262b Compare March 26, 2017 00:08

PetSerAl reviewed Mar 26, 2017

View reviewed changes

Changed TranscribeOnly member to a count rather than a bool so nested…

a2069d6

… -Trascript stays in TranscibeOnly Add try..finally in InternalDispose to ensure TranscribeOnlyCount gets decremented

SteveL-MSFT force-pushed the outdefault branch from 6dd262b to a2069d6 Compare March 26, 2017 03:16

added test case where garbage collection happens

4f509a3

SteveL-MSFT closed this Mar 27, 2017

SteveL-MSFT deleted the outdefault branch June 28, 2017 21:18

Out-Default incorrectly staying in transcript state #3392

Out-Default incorrectly staying in transcript state #3392

Conversation

SteveL-MSFT commented Mar 21, 2017

Uh oh!

PetSerAl left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

PetSerAl Mar 22, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

SteveL-MSFT commented Mar 23, 2017

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

SteveL-MSFT Mar 24, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

PetSerAl commented Mar 24, 2017

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

SteveL-MSFT commented Mar 24, 2017

Uh oh!

PetSerAl commented Mar 25, 2017

Uh oh!

SteveL-MSFT commented Mar 25, 2017

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

PetSerAl commented Mar 26, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

SteveL-MSFT commented Mar 27, 2017

Uh oh!

SteveL-MSFT commented Mar 27, 2017

Uh oh!

PetSerAl commented Mar 27, 2017

Uh oh!

SteveL-MSFT commented Mar 27, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

PetSerAl commented Mar 27, 2017

Uh oh!

SteveL-MSFT commented Mar 27, 2017

Uh oh!

PetSerAl commented Mar 27, 2017

Uh oh!

PetSerAl Mar 22, 2017 •

edited

Loading

SteveL-MSFT Mar 24, 2017 •

edited

Loading

PetSerAl commented Mar 26, 2017 •

edited

Loading

SteveL-MSFT commented Mar 27, 2017 •

edited

Loading