I can't figure out why, when running the following script, the second "write-output" does not appear in the transcript file ???

start-transcript -Path "c:\temp\test_transcript.txt" -Append;
    
$acl = Get-Acl "c:\temp";
$acl | Format-Table -Wrap;

Write-Output "1) A very simple message BEFORE new-item.";
New-Item -Path "C:\temp" -Name "test_file_$(get-date -f "yyyyMMdd_HHmmss").txt" -ItemType File -Verbose -ErrorAction Stop;

#Why is th second message not included int the transcript log file ???
Write-Output "2) A very simple message AFTER new-item.";

Stop-Transcript;

Here is what I get in the transcript file :

transcript file content

Does someone have an explanation for this ?

TRANSCRIPT FILE :

    Transcription démarrée, le fichier de sortie est c:\temp\test_transcript.txt
    
    
        Répertoire : C:\
    
    
    Path Owner              Access
    ---- -----              ------ temp MyDomain\MyUser BUILTIN\XXX Allow  FullControl
                            AUTORITE NT\XXX Allow  FullControl
                            BUILTIN\XXX Allow  ReadAndExecute, Synchronize
                            AUTORITE NT\XXX authentifiés Allow  Modify, Synchronize
    
    
    1) A very simple message BEFORE new-item.
EN CLAIR : Opération « Créer un fichier » en cours sur la cible « Destination : C:\temp\test_file_20230109_124005.txt ».
    
    **********************
Fin de la transcription Windows PowerShell
Heure de fin : 20230109124005
    **********************

CONSOLE :

Transcription démarrée, le fichier de sortie est c:\temp\test_transcript.txt


    Répertoire : C:\


Path Owner              Access
---- -----              ------
temp MyDomain\MyUser BUILTIN\XXX Allow  FullControl
                        AUTORITE NT\XXX Allow  FullControl
                        BUILTIN\XXX Allow  ReadAndExecute, Synchronize
                        AUTORITE NT\XXX authentifiés Allow  Modify, Synchronize


1) A very simple message BEFORE new-item.
EN CLAIR : Opération « Créer un fichier » en cours sur la cible « Destination : C:\temp\test_file_20230109_124005.txt ».


    Répertoire : C:\temp


Mode          LastWriteTime Length Name
----          ------------- ------ ----
-a---- 09/01/2023     12:40      0 test_file_20230109_124005.txt
2) A very simple message AFTER new-item.
Transcription arrêtée, le fichier de sortie est C:\temp\test_transcript.txt

CodePudding user response：

Building on the helpful comments:

tl;dr

• You're seeing a bug (though it isn't classified as such) that is one of several manifestations of asynchronous behavior when PowerShell implicitly applies Format-Table for-display formatting.

• Workarounds, all suboptimal, unfortunately:

  • Per-command [cumbersome, error-prone]: Use a Format-* cmdlet explicitly with any call that normally results in table formatting by default in order to force synchronous output; in your case, place | Format-Table after your New-Item call.

    • Note:
      • Using Format-Table prevents you from capturing a command's output as data, when you try to assign to a variable or process the output further in a pipeline, because what the Format-* cmdlets emit are formatting instructions, not data.

  • Script-wide [introduces a 300-msec delay]: As you've discovered, inserting a Start-Sleep at the end helps, under the following conditions:

    • The script must end with a command that synchronously outputs to the success output stream (i.e. is not implicitly table-formatted), such as the Write-Output "2) A very simple message AFTER new-item." call in your case. (Note that you may omit Write-Output to take advantage of PowerShell's implicit output behavior).

    • Start-Sleep -MilliSeconds 300 must be placed immediately before it, which forces the following synchronous output to also render the pending asynchronous output.

    • However, due to another design limitation in PowerShell's for-display output-formatting system that is separate from the asynchronous behavior (note that neither is specific to Start-Transcript use, but the latter manifests a cmdlet-specific way) there is pitfall if you don't use Format-Table calls explicitly:

      • If the first implicitly table-formatted statement in a script uses no predefined formatting-data, it locks in the display columns for all subsequent implicitly table-formatted statements, which can make the latters' output effectively invisible - see this answer.
      • Per-command Format-Table calls avoid this problem (while also forcing synchronous output), at the expense of not outputting data, as noted above.

A simplified example:

Start-Transcript t.txt

# This triggers *implicit* Format-Table output that is *asynchronous*,
# due to the output object having 4 or fewer properties and
# its type not having formatting-data associated with, as with the
# Get-Acl output in your question.
# NOTE:
#  * Curiously, the asynchronous behavior is also triggered in this case
#    if you append | Format-Table, but only affects SUBSEQUENT 
#    implicitly table-formatted statements, including those whose 
#    output types DO have formatting-data.
[pscustomobject] @{ Foo = 'Bar' }

# WORKAROUND:
#  Sleep for 300 msecs., then output *synchronously* to the success output stream.
#  This forces pending asynchronous table output to print. 
Start-Sleep -Milliseconds 300
"==== Done."

Stop-Transcript

You're seeing another manifestation of the infamous 300-msec. delay that occurs when Format-Table formatting is implicitly applied to output that goes to the display - see this answer for details.

While the typical manifestation is that output appears out of order (across different output streams), in your case information is lost, which is obviously a more serious problem. Data loss can also occur with the PowerShell CLI. See the GitHub issues below.

Relevant GitHub issues:

• GitHub issue #10994: the problem at hand (Start-Transcript-related).

  • The unfortunate conclusion appears to be that this will not be fixed.

• GitHub issue #4594: discussion of the surprising asynchronous behavior in general (output appearing out of order).

• GitHub issue #13985: potential data loss when using the CLI.