Log output of PowerShell psdebug trace to a file

Question

1. I have a script "B" from which I want to capture the debug output of Set-PSDebug -Trace n to a file. (File is the keyword here.)
2. I need to initiate the execution and debug capture of script "B" from another script, called A.

Example:

Script B:

Set-PSDebug -Trace 1

Function FuncA {
    Write-Host "ABC"
    FuncB
}

Function FuncB {
    Write-Host "123"
}

FuncA
FuncB

The correct debug output of this is:

DEBUG:   15+  >>>> FuncA
DEBUG:    6+ Function FuncA  >>>> {
DEBUG:    7+      >>>> Write-Host "ABC"
ABC
DEBUG:    8+      >>>> FuncB
DEBUG:   11+ Function FuncB  >>>> {
DEBUG:   12+      >>>> Write-Host "123"
123
DEBUG:   13+  >>>> }
DEBUG:    9+  >>>> }
DEBUG:   16+  >>>> FuncB
DEBUG:   11+ Function FuncB  >>>> {
DEBUG:   12+      >>>> Write-Host "123"
123
DEBUG:   13+  >>>> }

.

But when I try to run it now from script A via start-process to capture the output to a file:

$SParguments = "-NoProfile -file `"$stdTracefile`""
Start-Process 'C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe' -ArgumentList $SParguments -RedirectStandardOutput $stdTracelog

the output is oddly just this:

DEBUG:   15+  >>>> FuncA
DEBUG:    6+ Function FuncA  >>>> {
DEBUG:    7+      >>>> Write-Host "ABC"
ABC
123
123

The debugging messages stop after the first function, although the script finishes correctly.

Any ideas why and how to circumvent or avoid this?

Alternatively, I am looking for another solution to reach the two goals stated at the top.

BTW: I also tried using trace-command, which has a filepath parameter, but I don't know how to trace a whole script, and I do not know how to get the information Set-PSDebug provides: the lines being executed and the commands being executed, without all the rest. I want to automatically process the debug output, and the output of Set-PSDebug is exactly what I need.

Answer 1

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 1

Function FuncA {
    "ABC"
    FuncB
}

Function FuncB {
    "123"
}

FuncA
FuncB

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+  >>>> FuncA
DEBUG:    3+ Function FuncA  >>>> {
DEBUG:    4+      >>>> "ABC"
ABC
DEBUG:    5+      >>>> FuncB
DEBUG:    8+ Function FuncB  >>>> {
DEBUG:    9+      >>>> "123"
123
DEBUG:   10+  >>>> }
DEBUG:    6+  >>>> }
DEBUG:   13+  >>>> FuncB
DEBUG:    8+ Function FuncB  >>>> {
DEBUG:    9+      >>>> "123"
123
DEBUG:   10+  >>>> }