Tracing the script stack   1 comment

It’s not uncommon that after I’ve created a fairly complicated script after a while of using it, something bad happens that I wasn’t expecting. And I would really like to know how I got to this state, so a stacktrace of my script would be really, really nice. Sadly, this isn’t something that is a default behavior or PowerShell, but fortunately, this sort of thing is actually possible to do with just a little bit of script!

Most of the real world examples are more complicated than we really need to use to illuminate the problem.  So, I’ve created a simple example that is useful for discussion.

Take the following script:
# test-stacktrace1.ps1
param ( $startVal )
function func1
{
    param ( $startVal )
    1/$startVal–
    func2 $startVal
}
function func2
{
    param ( $startVal )
    1/$startVal–
    func3 $startVal
}
function func3
{
    param ( $startVal )
    1/$startVal–
}
func1 $startVal

When I run this script, depending on the value of my argument, the script will run or fail:

PS# c:\temp\test-stacktrace 5
0.2
0.25
0.333333333333333
PS# c:\temp\test-stacktrace1 2
0.5
1

Attempted to divide by zero.
At c:\temp\test-stacktrace1.ps1:18 char:7
+     1/$ <<<< startVal–

The message is ok – it tells me that I had a problem on the appropriate line in the script, but I don’t know how I got there by looking at the message.  What I would really like to see is both the error and the way I got there.  Here are some examples of what I want to see:

This example is the normal behavior
PS# c:\temp\test-stacktrace2 3
0.333333333333333
0.5
1

This example will show what happens when an error occurs deep in the stack:
PS# c:\temp\test-stacktrace2 2
0.5
1
func3 : Attempted to divide by zero.
At c:\temp\test-stacktrace2.ps1:25 char:10
+     func3  <<<< $startVal
At c:\temp\test-stacktrace2.ps1:31 char:42+     trap { write-error $_; get-stacktrace  <<<< }
At c:\temp\test-stacktrace2.ps1:25 char:10+     func3  <<<< $startVal
At c:\temp\test-stacktrace2.ps1:17 char:10+     func2  <<<< $startVal
At c:\temp\test-stacktrace2.ps1:36 char:6+ func1  <<<< $startVal
At line:1 char:25+ c:\temp\test-stacktrace2  <<<< 2

Notice that I see the functions that I called on the way to this error – This way I can see the path of woe that generated the error – which means I have a much better chance of actually fixing the problem. 

Here’s another example of what happens when an error occurs sooner in the stack, notice that we only see func1 and func2 calls:
PS# c:\temp\test-stacktrace2 1
1
func2 : Attempted to divide by zero.
At c:\temp\test-stacktrace2.ps1:17 char:10
+     func2  <<<< $startVal
At c:\temp\test-stacktrace2.ps1:23 char:42+     trap { write-error $_; get-stacktrace  <<<< }
At c:\temp\test-stacktrace2.ps1:17 char:10+     func2  <<<< $startVal
At c:\temp\test-stacktrace2.ps1:36 char:6+ func1  <<<< $startVal
At line:1 char:25+ c:\temp\test-stacktrace2  <<<< 1

And finally what happens when an error occurs right away, notice that we only see func1 in the stack:
PS# c:\temp\test-stacktrace2 0
func1 : Attempted to divide by zero.
At c:\temp\test-stacktrace2.ps1:36 char:6
+ func1  <<<< $startVal
At c:\temp\test-stacktrace2.ps1:15 char:42+     trap { write-error $_; get-stacktrace  <<<< }
At c:\temp\test-stacktrace2.ps1:36 char:6+ func1  <<<< $startVal
At line:1 char:25+ c:\temp\test-stacktrace2  <<<< 0

So, here’s the code – and a brief discussion follows:

param ( $startVal )
function get-stacktrace
{
    trap { continue }
    1..100 | %{
        $inv = &{ gv -sc $_ myinvocation } 2>$null
        if ($inv) { write-host -for blue $inv.value.positionmessage.replace("`n","") }
        }
    exit
}
function func1
{
    param ( $startVal )
    trap { write-error $_; get-stacktrace }
    1/$startVal–
    func2 $startVal
}
function func2
{
    param ( $startVal )
    trap { write-error $_; get-stacktrace }
    1/$startVal–
    func3 $startVal
}
function func3
{
    param ( $startVal )
    trap { write-error $_; get-stacktrace }
    1/$startVal
}
# Main
func1 $startVal

Notice the addition of the "get-stacktrace" function:

function get-stacktrace
{
    trap { continue }
    1..100 | %{
        $inv = &{ gv -sc $_ myinvocation } 2>$null
        if ($inv) { write-host -for blue $inv.value.positionmessage.replace("`n","") }
        }
    exit
}
 

This function takes advantage of the fact that the PowerShell scoping rules allow you to inspect variables in different scopes from your current scope.  This isn’t available via syntax, but it is available via the get-variable cmdlet (aliased to gv).  So our little get-stacktrace function just drills down our scopes looking for the myInvocation property which has the information about what line on the script we’re on.  There are some other things that are going on.  The trap statement assures me that if I get any terminating errors that I ignore them and I’ve placed the call of gv in a script block – this allows me to really throw away any messages that get-variable may throw that aren’t terminating errors.   Lastly, I want to be sure that my message is on a single line, so I replace the carriage returns with empty strings.

Notice also that each function now has a trap statement.  I think that this is generally good practice regardless, but these do two things.  First they write the error and then call the get-stacktrace function.  We need to write the error because the get-stacktrace function is going to exit, so if we didn’t have this write-error we wouldn’t actually see what the error was, just the stack trace which isn’t enough info.

So, if you’ve got a complicated script and you would really like to discover how you got where you are, I hope this little bit of script will help!

Jim

 

Advertisements

Posted July 15, 2007 by jtruher3 in PowerShell

One response to “Tracing the script stack

Subscribe to comments with RSS.

  1. I recently used a script like this and was disappointed to find that if I dumped the call stack in a top-level trap handler, the call stack had only one entry in it (the script startup) and was therefore useless.  I know the idea is to put traps in each function and invoke get-stacktrace there but that isn\’t realistic IMO.  I understand that by the time it gets to the top level trap handler all the necessary scopes are gone.  That leads me to the conclusion that this information should be included by PowerShell as part of the ErrorRecord.  We get an "internal" stack trace associated with the error.  It would be nice to get a script stack trace also.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: