Tracing the script stack

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