Fix conditions for transcription of Write-Information command. #6917

hubuk · 2018-05-22T06:03:03Z

PR Summary

Fix for #6916.

This change makes transcription of Write-Information command consistent with $InfomrationPreference variable.
Currently Write-Information command is being transcribed if $InfomrationPreference is set to 'SilentlyContinue' and not transcribed if set to 'Continue'.

The problem is in if/else statement which starts here:

PowerShell/src/System.Management.Automation/engine/MshCommandRuntime.cs

Lines 757 to 758 in 948532a

    
           if ((record.Tags.Contains("PSHOST") && (!record.Tags.Contains("FORWARDED"))) 
        
               || (preference == ActionPreference.Continue))

and has a continuation here:

PowerShell/src/System.Management.Automation/engine/MshCommandRuntime.cs

Lines 824 to 828 in 948532a

    
           else 
        
           { 
        
               // Only transcribe informational messages here. Transcription of PSHost-targeted messages is done in the InternalUI.Write* methods. 
        
               CBhost.InternalUI.TranscribeResult(StringUtil.Format(InternalHostUserInterfaceStrings.InformationFormatString, record.ToString())); 
        
           }

Transcription of Write-Host commands are handled in InternalUI.Write* methods as the comment suggests. These commands are distinguished by "PSHOST" tag.
Transcription of Write-Information commands is supposed to take place in the else statement but code in this statement is being executed only if

(!record.Tags.Contains("PSHOST") || record.Tags.Contains("FORWARDED"))
&&
preference != ActionPreference.Continue)

This condition is invalid. Correct condition is:

!record.Tags.Contains("PSHOST")
&&
preference == ActionPreference.Continue)

PR Checklist

iSazonov · 2018-05-22T10:43:37Z

@hubuk Thanks for your contribution. I believe we need to get a conclusion in Issue before we continue the PR.

hubuk · 2018-05-22T18:20:29Z

@iSazonov Sure. I need to check why a new test is failing. It was OK on my local machine.

hubuk · 2018-05-22T21:02:20Z

I found that tests are executed with redirection to a pipe.
In this case all Write-* commands are always logged in the transcript file no matter what preference is set.
According to this I removed the second test (no transcription for 'SilentlyContinue') as it cannot be satisfied by current test environment.

iSazonov · 2018-05-23T03:51:49Z

@mklement0 Could you please review the PR?

iSazonov

Leave a comment

iSazonov · 2018-05-23T03:52:22Z

test/powershell/Modules/Microsoft.Powershell.Host/Start-Transcript.Tests.ps1

+        & $script
+        Test-Path $transcriptFilePath | Should -BeTrue
+
+        $transcriptFilePath | Should FileContentMatch 'Continue'


Please use new syntax Should -FileContentMatch.

mklement0

Perhaps I'm missing something, but it it looks like you accidentally reverted the original fix.

hubuk · 2018-05-23T18:38:55Z

@mklement0 You are right. My bad...
And it proved that newly written test is not that useful...
Will fix it shortly.

hubuk · 2018-05-23T19:41:06Z

It should be OK now. Test was passing for the same reason why my previous test was failing.
All Write-* commands are transcribed if redirected to a pipe.

mklement0 · 2018-05-23T21:18:13Z

@hubuk:

All Write-* commands are transcribed if redirected to a pipe.

Can you clarify what that means, specifically, and perhaps give an example?
Is that a problem in itself or by-design behavior?

iSazonov · 2018-05-24T04:03:31Z

@hubuk Please don't fix CodeFactor issues in the PR (It's hard to review meaningful changes) - all style changes should be in new PR.

hubuk · 2018-05-24T06:15:56Z

@iSazonov Reverted the change.

@mklement0

All Write-* commands are transcribed if redirected to a pipe.

Sorry, for wrong information I provided:
Tests was failing because of too simple data to check. 'Continue' was also part of the pwsh.exe command line:
Host Application: ...\bin\Release\netcoreapp2.1\win7-x64\publish\pwsh.dll -noprofile -c $env:POWERSHELL_TELEMETRY_OPTOUT = 1;$ProgressPreference = 'silentlyContinue';...
and this is part of the transcription file.
I still need to investigate my previous observations. For now lets assume that this is not an issue.

iSazonov · 2018-05-25T07:17:07Z

Write-Host is related to this code so you have to add tests for it.

hubuk · 2018-05-27T19:27:20Z

@iSazonov I added tests for Write-Host with -InformationAction Continue and SilentlyContinue. Currently Ignore does not write to console but is being transcribed, so I skipped test for it. Let me know if you would like to have this test included anyway. I can also spend some time to make it produce same result for console and for transcript file. Fixing console output rather than transcription will make Write-Host behave as documented.

Additionally removing INFO: prefix mentioned by @mklement0 is easy. Should I proceed with it in this PR?

mklement0 · 2018-05-27T19:56:40Z

@hubuk:

Fixing console output rather than transcription will make Write-Host behave as documented.

I'm currently only aware of problems with the transcription behavior, not with console output, so the guiding principle should be to align transcription behavior with that of the current console-output behavior.

If, with respect to console-output behavior, you're referring to Write-Host being silenced by -InformationAction Ignore, that is not a behavioral problem, it is a documentation problem.

iSazonov

Style comments for all added tests

iSazonov · 2018-05-28T03:34:29Z

test/powershell/Modules/Microsoft.Powershell.Host/Start-Transcript.Tests.ps1

+        [String]$message = New-Guid
+        $script = {
+            Start-Transcript -Path $transcriptFilePath
+            Write-Host -Message $message -InformationAction SilentlyContinue


Please add test for Ignore for current behavior.

I think we should limit the PR to fix only transcript issues.

iSazonov · 2018-05-28T03:35:06Z

test/powershell/Modules/Microsoft.Powershell.Host/Start-Transcript.Tests.ps1

+            Stop-Transcript }
+        & $script
+        Test-Path $transcriptFilePath | Should -BeTrue
+


Please remove extra line.

iSazonov · 2018-05-28T03:35:20Z

test/powershell/Modules/Microsoft.Powershell.Host/Start-Transcript.Tests.ps1

+            Write-Information -Message $message -InformationAction Continue
+            Stop-Transcript }
+        & $script
+        Test-Path $transcriptFilePath | Should -BeTrue


Please add new line.

iSazonov · 2018-05-28T03:36:28Z

test/powershell/Modules/Microsoft.Powershell.Host/Start-Transcript.Tests.ps1

+        $script = {
+            Start-Transcript -Path $transcriptFilePath
+            Write-Information -Message $message -InformationAction Continue
+            Stop-Transcript }


Please use common formatting.

$script = { Start-Transcript -Path $transcriptFilePath Write-Information -Message $message -InformationAction Continue Stop-Transcript }

I used the same formatting as already applied for Transcription should record native command output test.

I see. I believe we should use the right pattern because It block and other code use right patterns.

I believe it is fixed, but $script block seems to be not needed and may be omitted.
What do you think?

It "Transcription should record Write-Host output when InformationAction is set to Ignore" { [String]$message = New-Guid Start-Transcript -Path $transcriptFilePath Write-Host -Message $message -InformationAction Ignore Stop-Transcript Test-Path $transcriptFilePath | Should -BeTrue $transcriptFilePath | Should -FileContentMatch $message }

Seems it is an isolation. I'am not sure that we should remove thos.

iSazonov · 2018-05-28T03:48:40Z

I'm not sure I need to remove the INFO: prefix. I suppose it was made that distinguish the output of the cmdlet. Although if we want to get the exact snapshot of the console then we need to remove this prefix

hubuk · 2018-05-28T08:53:00Z

There are two issues still present:

Write-Host -InformationAction Ignore is being transcribed but is should not be.
Write-Host -InformationAction Inquire has wrong order in transcript file:

> Write-Host 'Question?' -InformationAction Inquire
Question?

Confirm
Continue with this operation?
[Y] Yes  [A] Yes to All  [H] Halt Command  [S] Suspend  [?] Help (default is "Y"):

in transcript file:

Confirm
Continue with this operation?
&Yes  Yes to &All  &Halt Command  &Suspend
Y
Question?

The reason of 2. is that Write-Host is being transcribed separately in WriteConsoleCmdlet.cs file after the whole command has been handled.

Current transcript implementation for Write-Information can be used for Write-Host which will slightly simplify the code and provide fix for both 1. and 2.
May I include this fix in this PR?

mklement0 · 2018-05-28T14:57:13Z

@hubuk:

If there are no side effects, it seems like a good change to make (but it's not my call).

On a side note: the transcription of the prompt choices with the raw "accelerator chars." (&Yes instead of [Y] Yes) is unexpected (though not a big deal).

@iSazonov:

I'm not sure I need to remove the INFO: prefix. I suppose it was made that distinguish the output of the cmdlet. Although if we want to get the exact snapshot of the console then we need to remove this prefix

Yes, consistency with console output is important, I think.

However, you could argue that the INFO: prefix should be present in the console (as well), for consistency with the Write-Verbose, Write-Warning, and Write-Debug cmdlets, and that it is therefore console output that needs fixing in this case.

While changing that wouldn't technically be a breaking change - for-display output is not part of the contract with the user - it would be a noticeable one.

Either way, let's discuss it in a separate issue: #6951

mklement0 · 2018-05-30T21:15:41Z

Now that we know that the INFO: prefix is not printed to the console by design - see #6951 (comment) - we should remove it from the transcript too.

hubuk · 2018-06-04T10:28:41Z

@mklement0 @iSazonov
Made changes for two issues I mentioned.

Unfortunately "accelerator chars." are handled by PromptForChoice method in ConsoleHostUserInterfacePromptForChoice.cs file. Fix could be done by making part of this method public.

It seems like there could be much more cases in which transcription file is different from the console output. For example there is no transcription of an invalid accelerator keys user pressed.
Currently transcription code is spreed among entire codebase and it is hard to make it consistent with console output because host code may make changes to the data just before displaying it.

Better approach would be to make a transcript part of host classes which will make it easier to ensure consistency but it would be a major refactoring.

iSazonov · 2018-06-04T12:57:30Z

src/System.Management.Automation/engine/MshCommandRuntime.cs

@@ -748,7 +748,7 @@ internal void WriteInformation(InformationRecord record, bool overrideInquire =
                    //
                    if (null == Host || null == Host.UI)
                    {
-                        Diagnostics.Assert(false, "No host in CommandBase.WriteVerbose()");
+                        Diagnostics.Assert(false, "No host in CommandBase.WriteInformation()");
                        throw PSTraceSource.NewInvalidOperationException();


Please remove the Diagnostics.Assert an move the message string in

throw PSTraceSource.NewInvalidOperationException("No host in CommandBase.WriteInformation()");

iSazonov · 2018-06-04T13:15:23Z

src/System.Management.Automation/engine/MshCommandRuntime.cs

                {
-                    // Only transcribe informational messages here. Transcription of PSHost-targeted messages is done in the InternalUI.Write* methods.


Seems new comment about 'Inquire' and PSHost-targets will be useful.

Most important change is that transcription of Write-Host and Write-Information is handled in the same place now.
The part about fixing Inquire has only historical value and does not introduce any new information about current behavior.
Anyway, take a look at my comment and let me know if you want it stated differently as English is not my native language.

iSazonov · 2018-06-04T13:15:46Z

src/Microsoft.PowerShell.Commands.Utility/commands/utility/WriteConsoleCmdlet.cs

@@ -137,7 +137,6 @@ protected override void ProcessRecord()
            }

            this.WriteInformation(informationMessage, new string[] { "PSHOST" });
-            this.Host.UI.TranscribeResult(result);


Have we a test for this?

I already created three test for transcription of Write-Host command (Continue, SilentlyContinue, Ignore).
I have no idea how costly would it be to create a test for Inquire action as it makes the test interactive.

Ideally we should mosk but I don't know how.

@adityapatwardhan Can we ignore the lack of this test?

Is it possible to add a test hook?

Not clear where the hook should be to emulate the user interaction. Maybe in PromptForChoice method in ConsoleHostUserInterfacePromptForChoice.cs file?

@hubuk You can add hook here

PowerShell/src/System.Management.Automation/engine/Utils.cs

Line 1492 in c1c5344

public static class InternalTestHooks

, inject in PromptForChoice and use in the test.

That's great. Thanks.

Tests added.

mklement0 · 2018-06-04T13:19:58Z

@hubuk: Thanks for the update; my sense is that - at least for now and in the context of this PR - we needn't worry about transcribing 100% faithfully in all cases as long as all the information is ultimately there.

iSazonov · 2018-06-05T11:15:10Z

test/powershell/Modules/Microsoft.Powershell.Host/Start-Transcript.Tests.ps1

@@ -1,5 +1,8 @@
 # Copyright (c) Microsoft Corporation. All rights reserved.
 # Licensed under the MIT License.
+
+using namespace System.Management.Automation.Internal


Previously we don't use this in our tests so maybe remove this and use full names in tests.

iSazonov · 2018-06-05T11:29:13Z

src/Microsoft.PowerShell.ConsoleHost/host/msh/ConsoleHostUserInterfacePromptForChoice.cs

+            result = ReadLineResult.endedOnEnter;
+            return InternalTestHooks.ForcePromptForChoiceDefaultOption
+                   ? string.Empty
+                   : ReadLine(false, "", out result, true, true);


Sorry, I skipped this - please use string.Empty as in previous line.
Thank you for your patience. Seems this is my last comment.

Changed. Not a problem.

SteveL-MSFT · 2018-06-06T16:34:15Z

src/Microsoft.PowerShell.ConsoleHost/host/msh/ConsoleHostUserInterfacePromptForChoice.cs

+            result = ReadLineResult.endedOnEnter;
+            return InternalTestHooks.ForcePromptForChoiceDefaultOption
+                   ? string.Empty
+                   : ReadLine(false, string.Empty, out result, true, true);


Can you use named parameters here?

SteveL-MSFT · 2018-06-06T16:39:23Z

test/powershell/Modules/Microsoft.Powershell.Host/Start-Transcript.Tests.ps1

+        $newLine = [System.Environment]::NewLine
+        $expectedContent = "$message$($newLine)Confirm$($newLine)Continue with this operation?"
+        $script = {
+            [System.Management.Automation.Internal.InternalTestHooks]::SetTestHook('ForcePromptForChoiceDefaultOption', $True)


Seems like there should be an AfterEach{} that resets the test hook

SteveL-MSFT · 2018-06-06T16:41:09Z

test/powershell/Modules/Microsoft.Powershell.Host/Start-Transcript.Tests.ps1

+
+        & $script
+
+        Test-Path $transcriptFilePath | Should -BeTrue


Perhaps a search and replace to:

$transcriptFilePath | Should -Exist

…ode. Previously, the output sequencing of the message and the prompt choices differed between the host and the transcript.

…oiceResponse method. Simplified Start-Transcript tests.

hubuk · 2018-06-13T04:32:09Z

@SteveL-MSFT Is there anything else you would like to be changed?

iSazonov · 2018-06-14T18:08:20Z

@SteveL-MSFT Please update your review.

iSazonov · 2018-06-15T18:55:29Z

I have a fear of removal FORWARDED condition - do it really not used?

/cc @SteveL-MSFT Who can confirm?

hubuk · 2018-06-15T20:02:23Z

@iSazonov
FORWARDED condition is still there:

PowerShell/src/System.Management.Automation/engine/MshCommandRuntime.cs

Lines 756 to 757 in c67c20c

    
           if ((record.Tags.Contains("PSHOST") && (!record.Tags.Contains("FORWARDED"))) 
        
               || (preference == ActionPreference.Continue))

Only logic for the else statement has changed from:

PowerShell/src/System.Management.Automation/engine/MshCommandRuntime.cs

Lines 824 to 828 in e177fca

    
           else 
        
           { 
        
               // Only transcribe informational messages here. Transcription of PSHost-targeted messages is done in the InternalUI.Write* methods. 
        
               CBhost.InternalUI.TranscribeResult(StringUtil.Format(InternalHostUserInterfaceStrings.InformationFormatString, record.ToString())); 
        
           }

to:

PowerShell/src/System.Management.Automation/engine/MshCommandRuntime.cs

Lines 828 to 831 in c67c20c

    
           if (record.Tags.Contains("PSHOST") || (preference != ActionPreference.SilentlyContinue)) 
        
           { 
        
               CBhost.InternalUI.TranscribeResult(record.ToString()); 
        
           }

Before my changes TranscribeResult was being executed for the following conditions:

In WriteConsoleCmdlet.cs which is when record.Tags.Contains("PSHOST")
(preference != ActionPreference.Continue) && !record.Tags.Contains("PSHOST") as the first part of the evaluation of condition for else statement.
(preference != ActionPreference.Continue) && record.Tags.Contains("PSHOST") && record.Tags.Contains("FORWARDED") as the second part.
So transcription for FORWARDED tag was being executed only for Write-Host or for Write-Information when preference != ActionPreference.Continue. Taking into account that due to bug ActionPreference.Continue should be ActionPreference.SilentlyContinue This is what current code is doing.

After my changes TranscribeResult is being executed only for the following cases:

record.Tags.Contains("PSHOST")
!record.Tags.Contains("PSHOST") && preference != ActionPreference.SilentlyContinue

I hope this is somehow readable.

iSazonov · 2018-06-16T16:07:51Z

@hubuk Sorry, sometimes GitHub shows diffs in very strange way.

iSazonov · 2018-06-16T16:14:27Z

@hubuk Thank you for your contribution and your patience!
I hope you will make still many useful contributions.

hubuk · 2018-06-16T17:10:45Z

Happy to contribute. Thanks!

#6917)" This reverts commit 9ac701d.

hubuk requested review from BrucePay and daxian-dbw as code owners May 22, 2018 06:03

iSazonov reviewed May 23, 2018

View reviewed changes

mklement0 reviewed May 23, 2018

View reviewed changes

hubuk changed the title ~~Fix conditions for transcription of Write-Information command.~~ WIP Fix conditions for transcription of Write-Information command. May 24, 2018

hubuk changed the title ~~WIP Fix conditions for transcription of Write-Information command.~~ Fix conditions for transcription of Write-Information command. May 24, 2018

iSazonov reviewed May 28, 2018

View reviewed changes

mklement0 mentioned this pull request May 28, 2018

Should Write-Information output printed to the console have the "INFO: " prefix? #6951

Closed

hubuk requested review from dantraMSFT, JamesWTruher and PaulHigin as code owners June 4, 2018 10:08

iSazonov reviewed Jun 4, 2018

View reviewed changes

iSazonov reviewed Jun 5, 2018

View reviewed changes

iSazonov approved these changes Jun 5, 2018

View reviewed changes

iSazonov self-assigned this Jun 5, 2018

iSazonov requested a review from SteveL-MSFT June 6, 2018 05:00

SteveL-MSFT requested changes Jun 6, 2018

View reviewed changes

hubuk added 12 commits June 12, 2018 23:03

Fixed transcription of Write-Information command.

56386b1

Used new syntax for Should in Start-Transcript tests.

7536e3f

Transcribe redirected information records.

2fe68a6

Added tests for Write-Host transcription.

6f5b4a1

Added test for transcription of Write-Host -InformationAction Ignore.

16d7181

Removed INFO: prefix from Write-Information transcription.

d9e8f24

Fixed transcription for Write-Information -InformationAction Inquire.

056446d

Fixed script block code format.

2c6d024

Made Write-Host and Write-Information to use the same transcription c…

b2d9103

…ode. Previously, the output sequencing of the message and the prompt choices differed between the host and the transcript.

Fixed error reporting in WriteInformation method.

bae894d

Added tests for transcription of InformationAction Inquire.

d00d946

Unset test hook after tests execution. Use named parameters in ReadCh…

c67c20c

…oiceResponse method. Simplified Start-Transcript tests.

SteveL-MSFT approved these changes Jun 14, 2018

View reviewed changes

iSazonov merged commit 9ac701d into PowerShell:master Jun 16, 2018

hubuk mentioned this pull request Jun 16, 2018

Transcription of Write-Information works if preference is 'SilentlyContinue' #6916

Closed

hubuk deleted the issue6916 branch June 16, 2018 18:12

daxian-dbw added a commit that referenced this pull request Jun 19, 2018

Revert "Fix conditions for transcription of Write-Information command. (

30041e2

#6917)" This reverts commit 9ac701d.

	if ((record.Tags.Contains("PSHOST") && (!record.Tags.Contains("FORWARDED")))
	\|\| (preference == ActionPreference.Continue))

	else
	{
	// Only transcribe informational messages here. Transcription of PSHost-targeted messages is done in the InternalUI.Write* methods.
	CBhost.InternalUI.TranscribeResult(StringUtil.Format(InternalHostUserInterfaceStrings.InformationFormatString, record.ToString()));
	}

Fix conditions for transcription of Write-Information command. #6917

Fix conditions for transcription of Write-Information command. #6917

Conversation

hubuk commented May 22, 2018

PR Summary

PR Checklist

iSazonov commented May 22, 2018

hubuk commented May 22, 2018

hubuk commented May 22, 2018

iSazonov commented May 23, 2018

iSazonov left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mklement0 left a comment

Choose a reason for hiding this comment

hubuk commented May 23, 2018

hubuk commented May 23, 2018

mklement0 commented May 23, 2018

iSazonov commented May 24, 2018

hubuk commented May 24, 2018

iSazonov commented May 25, 2018

hubuk commented May 27, 2018 • edited Loading

mklement0 commented May 27, 2018

iSazonov left a comment

Choose a reason for hiding this comment

iSazonov May 28, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

hubuk May 28, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

iSazonov commented May 28, 2018

hubuk commented May 28, 2018 • edited Loading

mklement0 commented May 28, 2018

mklement0 commented May 30, 2018

hubuk commented Jun 4, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mklement0 commented Jun 4, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

hubuk commented Jun 13, 2018

iSazonov commented Jun 14, 2018

iSazonov commented Jun 15, 2018

hubuk commented Jun 15, 2018 • edited Loading

iSazonov commented Jun 16, 2018

iSazonov commented Jun 16, 2018

hubuk commented Jun 16, 2018

hubuk commented May 27, 2018 •

edited

Loading

iSazonov May 28, 2018 •

edited

Loading

hubuk May 28, 2018 •

edited

Loading

hubuk commented May 28, 2018 •

edited

Loading

hubuk commented Jun 4, 2018 •

edited

Loading

mklement0 commented Jun 4, 2018 •

edited

Loading

hubuk commented Jun 15, 2018 •

edited

Loading