1

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
RaFla
  • 13
  • 3
  • 1
    Does the `New-Item` complete successfully? Because `-ErrorAction Stop` causes the effect you are seeing, The script stops at that point if the New-Item causes an error. – Scepticalist Jan 09 '23 at 12:01
  • Wrap your `New-Item` in a `try{}catch{}` block, and see what shows up in the transcript: `try { New-Item -Path "C:\temp" -Name "test_file_$(get-date -f "yyyyMMdd_HHmmss").txt" -ItemType File -Verbose -ErrorAction Stop} catch {"New-Item failed!"}` - I would expect that if the `New-Item` fails, you'll see `New-Item failed!` in your transcript. – Jeff Zeitlin Jan 09 '23 at 12:12
  • Also, just to avoid any possibility of confusion between the [`-f` operator](https://ss64.com/ps/syntax-f-operator.html) and the `-Format` parameter of `Get-Date`, use `-For` instead of `-f` as the parameter to `Get-Date`. – Jeff Zeitlin Jan 09 '23 at 12:15
  • Thanks. The new-item complete successfully. But I will double-check, write try/catch as you say and keep you informed. – RaFla Jan 09 '23 at 13:01
  • Exact same behavior with try...catch and -For instead of -f. There are no errors but the second message does not appear. I must admit I'm lost... – RaFla Jan 09 '23 at 13:14
  • @Scepticalist - the screenshot shows a footer in the file from ```Stop-Transcript``` so *presumably* the script ran to completion. I thought it *might* be something to do with the 300ms delay built into ```Format-Table``` further up the script, meaning ```Stop-Transcript``` gets called before all the output is written to transcript, but I couldn't reproduce the issue locally to test that. – mclayton Jan 09 '23 at 13:47
  • Interesting : I wasn't aware of this 300ms delay : it might be an explanation. Can I insert a Start-Sleep() at the end of my script ? would that solve the problm ? Or is there some kind of flush() method ? One thing for sure : removing the format-table line solves the problem. – RaFla Jan 09 '23 at 14:43
  • Smells like this known issue: https://github.com/PowerShell/PowerShell/issues/10994 – Bacon Bits Jan 09 '23 at 14:44
  • Thanks @BaconBits : very interesting link. I haven't read everything yet, but it looks pretty close. – RaFla Jan 09 '23 at 14:48
  • A simple workaround would be to pipe any “implicit” output to ```Out-Host``` or ```Out-String``` to make it “explicit”. .e.g. ```Write-Output … | Out-Host``` which turns it into blocking operation that will complete before the next line is called. That’ll add a lot of cruft to your code though. I don’t think ```Start-Sleep``` will work because it blocks ```Format-Table``` as far as I can remember so you’ll just be in the same position 2 seconds later. Feel free to try it and prove me wrong though :-) – mclayton Jan 09 '23 at 17:59

1 Answers1

1

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. it must not be implicitly table-formatted), notably by outputting a string, such as in your Write-Output "2) A very simple message AFTER new-item." call. (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 in a way that is specific to that cmdlet) there is general 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:

mklement0
  • 382,024
  • 64
  • 607
  • 775
  • 1
    Great answer ! I ended up adding a line "Start-Sleep -Seconds 1;" before my last call to write-output. Surely not the msot elegant solution, but this avoids the need to put "| format-table" after every non-string object. Plus 1s delay at the end of the script is no big deal in my context. Thanks for all the help ! – RaFla Jan 09 '23 at 15:53