PowerShell v2 PSDebug Free Backstage Limited Pass to the Show

This going a little old school, back to the MSH prefxies, but, Ill bring it up to speed shortly. While looking around the other day I stumbled across Jeffrey Snovers post:

Debugging Monad Scripts, Part 4: set-mshdebug 

In the post we see the roots of the current cmdlet Set-PSDebug. If you have never used this cmdlet it can be very helpful in pointing out issues that may be hampering sucessfully running some command or script. Being the ever vigilant tinkerer I am I decided to play with this and found some cool things. Aside from the realization that $ErrorView could be played with and was tested in the process of running PSDebug I saw a new ability to peek under the hood of just what all was going on when things ran. Now, I am coming to look at things in a variety of layers.

 First, you can code your scripts with [CmdletBinding()] and Write-Verbose to give you two modes: regular or verbose. This adds a lot of overhead, however, as you have to write a good bit of extra code, depending on how much you want to tell yourself with -Verbose. Still, there are times where you want to be able to see whats really going on in depth without running secodary cmdlets or forcing folks inexperienced in dealing with debugging interactively. Fair enough, I still see Verbose as having its place and use it all the time.

 A second case, however, which I see as having two flavors, focuses on the user who does have debugging chops and does not have the time or need to write chatty, Verbose laded scripts. Okay, again, fair enough. A good distinction for larger projects I must confess. For this second crew, writing scripts, debugging scripts (or cmdlets/modules you didnt write) and general noodling with things otherwise left alone there are other ways to do diagnostics, engineering and post mortem via the shell. While I would like to go over the Debug cmdlets in depth-and, probably will one day-the goal here is to focus on what you see when you work with the PSDebug cmdlets. Instead of focusing on explaining on how it all works (there are lots of posts out there to cover this) I want to look at what you will see once you get past the help and start breaking stuff. Lets start with something broken like this:

dir 1 | % { $_ }

Simple enough. If you run this with PSDebug you get this (assuming $ErrorView is not set to CategoryView):

Get-ChildItem : Cannot find path C:Windowssystem321 because it does not exist.
At line:1 char:4
+ dir <<<< 1 | % { $_ }
+ CategoryInfo : ObjectNotFound: (C:Windowssystem321:String) [Get-ChildItem], ItemNotFoundException
+ FullyQualifiedErrorId : PathNotFound,Microsoft.PowerShell.Commands.GetChildItemCommand

Ok. Underwhelming. The regular I-messed-up red. So what? We knew this would break something. Now, let us have a little more fun. First, enable PSDebug:

PS C:Windowssystem32> Set-PSDebug -Trace 2

gives me

DEBUG: 2+ $foundSuggestion = <&;lt;<< $false
DEBUG: ! SET $foundSuggestion = False.
DEBUG: 4+ if <<<< ($lastError -and
DEBUG: 15+ $foundSuggestion <<<<<

Again, nothing special yet. Just some feedback indicating -Trace level 2 is on. (You see the ! SET calls with level 2). Alright, time for my special cmdlet c-4:

PS > dir 1 | % { $_ }
DEBUG: 1+ <<<< dir 1 | % { $_ }
DEBUG: 2+ if <<<< ($_.FullyQualifiedErrorId -ne "NativeCommandErrorMessage"
-and $ErrorView -ne "CategoryView") {
DEBUG: 3+ $myinv = <<<< $_.InvocationInfo
DEBUG: ! SET $myinv = System.Management.Automation.InvocationInfo.
DEBUG: 4+ switch <<<< -regex ( & { Set-StrictMode -Version 1;
$myinv.MyCommand.CommandType } )
DEBUG: ! CALL scriptblock.
DEBUG: 4+ switch -regex ( & { <<<< Set-StrictMode -Version 1;
$myinv.MyCommand.CommandType } )
DEBUG: 4+ switch -regex ( & { Set-StrictMode -Version 1; $myinv.MyCommand.
<<<< CommandType } )
DEBUG: 24+ if <<<< ( & { Set-StrictMode -Version 1;
$myinv.MyCommand.Name } )
DEBUG: ! CALL scriptblock.
DEBUG: 24+ if ( & { <<<< Set-StrictMode -Version 1;
$myinv.MyCommand.Name } )
DEBUG: 24+ if ( & { Set-StrictMode -Version 1; $myinv.MyCommand. <<<<
Name } )
DEBUG: 26+ $myinv.MyCommand.Name + <<<< " : "; break;
DEBUG: 26+ $myinv.MyCommand.Name + " : "; break <<<< ;
DEBUG: 2+ if <<<< ($_.FullyQualifiedErrorId -eq "NativeCommandErrorMessage") {
DEBUG: 7+ if <<<< ($_.InvocationInfo) {
DEBUG: 8+ $posmsg = <<<< $_.InvocationInfo.PositionMessage
DEBUG: ! SET $posmsg =
At line:1 char:4
+ dir <<<< 1 | % { $_ } .
DEBUG: 13+ if <<<< ( & { Set-StrictMode -Version 1; $_.PSMessageDetails } )
{
DEBUG: ! CALL scriptblock.
DEBUG: 13+ if ( & { <<<< Set-StrictMode -Version 1; $_.PSMessageDetails } )
{
DEBUG: 13+ if ( & { Set-StrictMode -Version 1; $_. <<<< PSMessageDetails } )
{
DEBUG: 1+ <<<< & { Set-StrictMode -Version 1; $this.Exception.InnerException.PSMessageDetails }
DEBUG: ! CALL scriptblock.
DEBUG: 1+ & { <<<< Set-StrictMode -Version 1; $this.Exception.InnerException.PSMessageDetails }
DEBUG: 1+ & { Set-StrictMode -Version 1; $this.Exception.InnerException. <<<< PSMessageDetails }
DEBUG: 17+ $indent = <<<< 4
DEBUG: ! SET $indent = 4.
DEBUG: 18+ $width = <<<< $host.UI.RawUI.BufferSize.Width - $indent - 2
DEBUG: ! SET $width = 114.
DEBUG: 20+ $indentString = <<<< "+ CategoryInfo : " +
$_.CategoryInfo
DEBUG: ! SET $indentString = + CategoryInfo : ObjectNotFound: (C:Wi....
DEBUG: 21+ $posmsg += <<<< "`n"
DEBUG: ! SET $posmsg =
At line:1 char:4
+ dir <<<< 1 | % { $_ }
.
DEBUG: 22+ foreach <<<< ($line in @($indentString -split "(.{$width})")) {
if($line) { $posmsg += (" " * $indent + $line) } }
DEBUG: 22+ foreach($line in @($indentString -split <<<< "(.{$width})")) {
if($line) { $posmsg += (" " * $indent + $line) } }
DEBUG: 22+ foreach($line in @($indentString -split "(.{$width})")) { if <<<<
($line) { $posmsg += (" " * $indent + $line) } }
DEBUG: 22+ foreach($line in @($indentString -split "(.{$width})")) {
if($line) { $posmsg += <<<< (" " * $indent + $line) } }
DEBUG: ! SET $posmsg =
At line:1 char:4
+ dir <<<< 1 | % { $_ }
+ Cate....
DEBUG: 24+ $indentString = <<<< "+ FullyQualifiedErrorId : " +
$_.FullyQualifiedErrorId
DEBUG: ! SET $indentString = + FullyQualifiedErrorId : PathNotFound,Microsoft....
DEBUG: 25+ $posmsg += <<<< "`n"
DEBUG: ! SET $posmsg =
At line:1 char:4
+ dir <<<< 1 | % { $_ }
+ Cate....
DEBUG: 26+ foreach <<<< ($line in @($indentString -split "(.{$width})")) {
if($line) { $posmsg += (" " * $indent + $line) } }
DEBUG: 26+ foreach($line in @($indentString -split <<<< "(.{$width})")) {
if($line) { $posmsg += (" " * $indent + $line) } }
DEBUG: 26+ foreach($line in @($indentString -split "(.{$width})")) { if <<<<
($line) { $posmsg += (" " * $indent + $line) } }
DEBUG: 26+ foreach($line in @($indentString -split "(.{$width})")) {
if($line) { $posmsg += <<<< (" " * $indent + $line) } }
DEBUG: ! SET $posmsg =
At line:1 char:4
+ dir <<<< 1 | % { $_ }
+ Cate....
DEBUG: 28+ if <<<< ($ErrorView -eq "CategoryView") {
DEBUG: 32+ $_.Exception.Message + <<<< $posmsg + "`n "
Get-ChildItem : Cannot find path C:Windowssystem321 because it does not exist.
At line:1 char:4
+ dir <<<< 1 | % { $_ }
+ CategoryInfo : ObjectNotFound: (C:Windowssystem321:String) [Get-ChildItem], ItemNotFoundException
+ FullyQualifiedErrorId : PathNotFound,Microsoft.PowerShell.Commands.GetChildItemCommand

DEBUG: 2+ $foundSuggestion = <<<< $false
DEBUG: ! SET $foundSuggestion = False.
DEBUG: 4+ if <<<< ($lastError -and
DEBUG: 15+ $foundSuggestion <<<<

Yeah, now thats what Im talking about. Damage. At first it looks like a lot more than whats really going on. See, PSDebug, when you set trace to 2, gives a lot of output. For reference, here is level 1 devestation:

PS C:Windowssystem32> Set-PSDebug -Trace 1
DEBUG: 1+ <<<< Set-PSDebug -Trace 1
DEBUG: 2+ $foundSuggestion = <<<< $false
DEBUG: 4+ if <<<< ($lastError -and
DEBUG: 15+ $foundSuggestion <<<<
PS C:Windowssystem32> dir 1 | % { $_ }
DEBUG: 1+ <<<< dir 1 | % { $_ }
DEBUG: 2+ if <<<< ($_.FullyQualifiedErrorId -ne "NativeCommandErrorMessage"
-and $ErrorView -ne "CategoryView") {
DEBUG: 3+ $myinv = <<<< $_.InvocationInfo
DEBUG: 4+ switch <<<< -regex ( & { Set-StrictMode -Version 1;
$myinv.MyCommand.CommandType } )
DEBUG: 4+ switch -regex ( & { <<<< Set-StrictMode -Version 1;
$myinv.MyCommand.CommandType } )
DEBUG: 4+ switch -regex ( & { Set-StrictMode -Version 1; $myinv.MyCommand.
<<<< CommandType } )
DEBUG: 24+ if <<<< ( & { Set-StrictMode -Version 1;
$myinv.MyCommand.Name } )
DEBUG: 24+ if ( & { <<<< Set-StrictMode -Version 1;
$myinv.MyCommand.Name } )
DEBUG: 24+ if ( & { Set-StrictMode -Version 1; $myinv.MyCommand. <<<<
Name } )
DEBUG: 26+ $myinv.MyCommand.Name + <<<< " : "; break;
DEBUG: 26+ $myinv.MyCommand.Name + " : "; break <<<< ;
DEBUG: 2+ if <<<< ($_.FullyQualifiedErrorId -eq "NativeCommandErrorMessage") {
DEBUG: 7+ if <<<< ($_.InvocationInfo) {
DEBUG: 8+ $posmsg = <<<< $_.InvocationInfo.PositionMessage
DEBUG: 13+ if <<<< ( & { Set-StrictMode -Version 1; $_.PSMessageDetails } )
{
DEBUG: 13+ if ( & { <<<< Set-StrictMode -Version 1; $_.PSMessageDetails } )
{
DEBUG: 13+ if ( & { Set-StrictMode -Version 1; $_. <<<< PSMessageDetails } )
{
DEBUG: 1+ <<<< & { Set-StrictMode -Version 1; $this.Exception.InnerException.PSMessageDetails }
DEBUG: 1+ & { <<<< Set-StrictMode -Version 1; $this.Exception.InnerException.PSMessageDetails }
DEBUG: 1+ & { Set-StrictMode -Version 1; $this.Exception.InnerException. <<<< PSMessageDetails }
DEBUG: 17+ $indent = <<<< 4
DEBUG: 18+ $width = <<<< $host.UI.RawUI.BufferSize.Width - $indent - 2
DEBUG: 20+ $indentString = <<<< "+ CategoryInfo : " +
$_.CategoryInfo
DEBUG: 21+ $posmsg += <<<< "`n"
DEBUG: 22+ foreach <<<< ($line in @($indentString -split "(.{$width})")) {
if($line) { $posmsg += (" " * $indent + $line) } }
DEBUG: 22+ foreach($line in @($indentString -split <<<< "(.{$width})")) {
if($line) { $posmsg += (" " * $indent + $line) } }
DEBUG: 22+ foreach($line in @($indentString -split "(.{$width})")) { if <<<<
($line) { $posmsg += (" " * $indent + $line) } }
DEBUG: 22+ foreach($line in @($indentString -split "(.{$width})")) {
if($line) { $posmsg += <<<< (" " * $indent + $line) } }
DEBUG: 24+ $indentString = <<<< "+ FullyQualifiedErrorId : " +
$_.FullyQualifiedErrorId
DEBUG: 25+ $posmsg += <<<< "`n"
DEBUG: 26+ foreach <<<< ($line in @($indentString -split "(.{$width})")) {
if($line) { $posmsg += (" " * $indent + $line) } }
DEBUG: 26+ foreach($line in @($indentString -split <<<< "(.{$width})")) {
if($line) { $posmsg += (" " * $indent + $line) } }
DEBUG: 26+ foreach($line in @($indentString -split "(.{$width})")) { if <<<<
($line) { $posmsg += (" " * $indent + $line) } }
DEBUG: 26+ foreach($line in @($indentString -split "(.{$width})")) {
if($line) { $posmsg += <<<< (" " * $indent + $line) } }
DEBUG: 28+ if <<<< ($ErrorView -eq "CategoryView") {
DEBUG: 32+ $_.Exception.Message + <<<< $posmsg + "`n "
Get-ChildItem : Cannot find path C:Windowssystem321 because it does not exist.
At line:1 char:4
+ dir <<<< 1 | % { $_ }
+ CategoryInfo : ObjectNotFound: (C:Windowssystem321:String) [Get-ChildItem], ItemNotFoundException
+ FullyQualifiedErrorId : PathNotFound,Microsoft.PowerShell.Commands.GetChildItemCommand

DEBUG: 2+ $foundSuggestion = <<<< $false
DEBUG: 4+ if <<<< ($lastError -and
DEBUG: 15+ $foundSuggestion <<<<

Still a lot to wade through, but, you are not seeing every single evaluation along the way. As noted in Get-Help:

-Trace <int>
Specifies the trace level:
0 - Turn script tracing off
1 - Trace script lines as they are executed
2 - Trace script lines, variable assignments, function calls, and scripts.

Alright, so, what can we really see going on here? Essentially, in this case, we are watching an error occur, then, PowerShell respond to the error to build the ErrorRecord message to be output to the console. Each time you see a set of less than signs (<) this indicates what the Shell is operating on in that moment. So, we can set -Step to allow us to suspend things, and, look around to see what is going along the way. So, lets do just that:

PS > Set-PSDebug -Trace 2 -Step

Continue with this operation?
1+ <<<< Set-PSDebug -Trace 2 -Step
[Y] Yes [A] Yes to All [N] No [L] No to All [S] Suspend [?] Help (default is "Y"): a
DEBUG: 1+ <<<< Set-PSDebug -Trace 2 -Step

Continue with this operation?
2+ $foundSuggestion = <<<< $false
[Y] Yes [A] Yes to All [N] No [L] No to All [S] Suspend [?] Help (default is "Y"): a
DEBUG: 2+ $foundSuggestion = <<<< $false
DEBUG: ! SET $foundSuggestion = False.
DEBUG: 4+ if <<<< ($lastError -and
DEBUG: 15+ $foundSuggestion <<<<

This is just how thing goes with -Step enabled. No worries. You have to approve every action of the parser and the engine. Ill step in a few lines and get to something interesting:

PS > dir 1 | % { $_ }

Continue with this operation?
1+ <<<< dir 1 | % { $_ }
[Y] Yes [A] Yes to All [N] No [L] No to All [S] Suspend [?] Help (default is "Y"): y
DEBUG: 1+ <<<< dir 1 | % { $_ }

Continue with this operation?
2+ if <<<< ($_.FullyQualifiedErrorId -ne "NativeCommandErrorMessage" -and
$ErrorView -ne "CategoryView") {
[Y] Yes [A] Yes to All [N] No [L] No to All [S] Suspend [?] Help (default is "Y"): y
DEBUG: 2+ if <<<< ($_.FullyQualifiedErrorId -ne "NativeCommandErrorMessage"
-and $ErrorView -ne "CategoryView") {

Continue with this operation?
3+ $myinv = <<<< $_.InvocationInfo
[Y] Yes [A] Yes to All [N] No [L] No to All [S] Suspend [?] Help (default is "Y"): s
PS >>> $myinv
PS >>> $_
Get-ChildItem : Cannot find path C:1 because it does not exist.
At line:1 char:4
+ dir <<<< 1 | % { $_ }
+ CategoryInfo : ObjectNotFound: (C:1:String) [Get-ChildItem], ItemNotFoundException
+ FullyQualifiedErrorId : PathNotFound,Microsoft.PowerShell.Commands.GetChildItemCommand

PS C:>>> $_.InvocationInfo


MyCommand : Get-ChildItem
BoundParameters : {[Path, System.String[]]}
UnboundArguments : {}
ScriptLineNumber : 1
OffsetInLine : 4
HistoryId : 23
ScriptName :
Line : dir 1 | % { $_ }
PositionMessage :
At line:1 char:4
+ dir <<<< 1 | % { $_ }
InvocationName : dir
PipelineLength : 2
PipelinePosition : 1
ExpectingInput : False
CommandOrigin : Runspace

Well, again, a lot of output. But, as we dig in, we can see that an error occurs as the engine attempts to parse the command. Once I get just past the error I want to stop and poke around. In in this case, I want to see what the pipelined objects InvocationInfo object looks like. Now, you cant normally catch this until after this script has completed processing and the error has already been caught and reported. Here, as we are walking through in flight, we can see exactly what the settings of certain variables (in this case PowerShell internal variables) tell us. Normally, these are mechanics inaccessible to the script operator, but, using this approach, we can find a lot about what is really going on under the hood.

That should be enough to start chewing on for a Friday afternoon before the weekend. Let me know what cool stuff you this backstage pass lets you check out.