Log output of PowerShell psdebug trace to a file

So, here's what I learned with some testing in PowerShell v4.0, using both the ISE and the regular host.

1. Using any of the Write- cmdlets seemed to interrupt the PSDebug output from the point that the first of those cmdlets is encountered. Commenting them out, e.g. the Write-Host "ABC" line would allow more trace to be seen until the Write-Host in FuncB was called.

2. Using return fixed the problem, although it did mean that FuncB wasn't called from within FuncA, simply due to the logical flow of the script.

3. Stripping things back to just the string itself seemed to result in the expected behaviour. By this I mean simply removing the Write-Host cmdlet and leaving the "ABC" and "123" parts. I'm not fan in spitting out text like this from functions, but at least it gave what we're expecting in this example. See below.

4. Leaving a blank line at the end of Script A changed the behaviour of the output, i.e. if there is a carriage return at the end of line 13 then the output is formatted as shown below. If not, then you'd end up with two lines of debug on the same line:

   DEBUG: 13+ >>>> FuncBDEBUG: 8+ Function FuncB >>>> {

5. Running in PowerShell 5.0 mostly fixes the (original post) problem, although I still had problems with DEBUG lines running on immediately after the Write-Host output (i.e. without a newline). Again, switching to the code in the solution below fixed the output.

   ABCDEBUG: 5+ >>>> FuncB

Solution

Script A: C:\Scripts\PowerShell\Test-Debug.ps1

Set-PSDebug -Trace 1Function FuncA {    "ABC"    FuncB}Function FuncB {    "123"}FuncAFuncB

Script B: : C:\Scripts\PowerShell\Call-TestDebug.ps1

$stdTraceFile = "C:\Scripts\PowerShell\Test-Debug.ps1"$stdTraceLog  = Join-Path $env:TEMP test.log$PSExecutable = 'C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe'$SParguments = "-Version 4 -NoProfile -File $stdTracefile"Start-Process -FilePath $PSExecutable -ArgumentList $SParguments `  -RedirectStandardOutput $stdTracelog

This gave the output that I think you were expecting in test.log:

DEBUG:   12+  >>>> FuncADEBUG:    3+ Function FuncA  >>>> {DEBUG:    4+      >>>> "ABC"ABCDEBUG:    5+      >>>> FuncBDEBUG:    8+ Function FuncB  >>>> {DEBUG:    9+      >>>> "123"123DEBUG:   10+  >>>> }DEBUG:    6+  >>>> }DEBUG:   13+  >>>> FuncBDEBUG:    8+ Function FuncB  >>>> {DEBUG:    9+      >>>> "123"123DEBUG:   10+  >>>> }

Solution: Use PowerShell 5!

I have had a quick look on MS Connect to see if there is any hint of this being a known/reported bug but haven't found anything. HOWEVER, the fact that the behaviour changes in PSv5 suggests that there has been a fix, possibly with the introduction of the Information output stream.

If you can't modify the scripts which are currently calling Write-Host, etc. then, from our collective testing, I'm not sure there is a fix other than to use PowerShell 5. Obviously not a trivial proposal if you have a large/controlled environment.