Log output of PowerShell psdebug trace to a file

Question

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.)
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.

I am unable to reproduce your problem, neither from the PowerShell console nor the ISE. I always get the correct output you listed, minus a carriage return or two. Which version of PowerShell are you running (available in the $PSVersionTable variable)? — JamesQMurphy
– JamesQMurphy, Commented Apr 1, 2016 at 23:15
Also, instead of spinning up PowerShell with Start-Process, what happens if you just call it directly, using .\b.ps1? — JamesQMurphy
– JamesQMurphy, Commented Apr 1, 2016 at 23:19
I use v4 and after your comment just tried it on v3. Same result. I tried the console, ISE and PowerGUI. Dot-sourcing is not an option because 1. i dont wont the script in my runspace , but more important redirection of the debug output to a file does not work fully, because redirection with "5>" does not include the line numbers of the trace and they are vital for me. — Rob
– Rob, Commented Apr 1, 2016 at 23:28
Just tested it on v5, which works. And has way more output, btw. :/ So this might be a bug. Unfortunately using v5 is not possible, it need to find a solution for v4. Maybe there is another way to redirect the output to a file, apart from Start-process.... — Rob
– Rob, Commented Apr 1, 2016 at 23:40
I don't think it's a bug... I suspect that Set-PSDebug uses Write-Host. PowerShell 5.0 changed the way Write-Host works (it now writes to the Information Stream, aka stream 6). However, even running your example with PowerShell 2.0 still didn't recreate the bug on my end. Sorry. — JamesQMurphy
– JamesQMurphy, Commented Apr 2, 2016 at 1:39

MisterSeajay · Accepted Answer · 2016-04-08 22:31:43Z

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

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.
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.
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.
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 >>>> {
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+  >>>> }

Thanks for the effort, but Script B was of course just an example. This needs to work with multiple scripts which i can not edit.

MisterSeajay · Accepted Answer · 2016-04-09 20:38:34Z

1

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.

answered Apr 9, 2016 at 20:38

MisterSeajay

4,7891 gold badge28 silver badges53 bronze badges

2 Comments

Rob Over a year ago

I know that it works with v5, I said that in the comments to my OP. But an upgrade to v5 is not an option unfortunately.

MisterSeajay Over a year ago

Yeah, I saw that. However this might be a workable answer for someone else who stumbles upon this question... :-)

Dennis · Accepted Answer · 2023-12-18 17:06:21Z

0

The module PowerShellLogging might get some new project resources/a hand over, that will bring it up-to-date with the latest releases of PowerShell..

answered Dec 18, 2023 at 17:06

Dennis

2,1282 gold badges20 silver badges46 bronze badges

Collectives™ on Stack Overflow

Log output of PowerShell psdebug trace to a file

3 Answers 3

Solution

2 Comments

2 Comments

Comments

Your Answer

Hot Network Questions

Collectives™ on Stack Overflow

3 Answers 3

Solution

2 Comments

2 Comments

Comments

Your Answer

Sign up or log in

Post as a guest

Related