{"id":72192,"date":"2015-07-13T00:01:00","date_gmt":"2015-07-13T00:01:00","guid":{"rendered":"https:\/\/blogs.technet.microsoft.com\/heyscriptingguy\/2015\/07\/13\/tracing-the-execution-of-a-powershell-script\/"},"modified":"2019-02-18T09:47:01","modified_gmt":"2019-02-18T16:47:01","slug":"tracing-the-execution-of-a-powershell-script","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/scripting\/tracing-the-execution-of-a-powershell-script\/","title":{"rendered":"Tracing the Execution of a PowerShell Script"},"content":{"rendered":"<p><b style=\"font-size:12px\">Summary<\/b><span style=\"font-size:12px\">: Ed Wilson, Microsoft Scripting Guy, talks about using a cmdlet to trace the execution of a Windows PowerShell script.<\/span><\/p>\n<p><img decoding=\"async\" src=\"https:\/\/devblogs.microsoft.com\/wp-content\/uploads\/sites\/29\/2019\/02\/q-for-powertip.jpg\" alt=\"Hey, Scripting Guy! Question\" \/>&nbsp;Hey, Scripting Guy! I am having a problem with a script. It does not generate any errors, but dude, it does not seem to work either. Can you help me debug it?<\/p>\n<p>&mdash;DR<\/p>\n<p><img decoding=\"async\" src=\"https:\/\/devblogs.microsoft.com\/wp-content\/uploads\/sites\/29\/2019\/02\/a-for-powertip.jpg\" alt=\"Hey, Scripting Guy! Answer\" \/>&nbsp;Hello DR,<\/p>\n<p>Microsoft Scripting Guy, Ed Wilson, is here. When I see a script that doesn&rsquo;t work, I think, &quot;Cool&hellip;it is easy to troubleshoot.&quot; Often this is the case because the error message helps locate the source of the error. But if a script simply doesn&rsquo;t work, it can be more difficult to troubleshoot. If the error is a logic error, it can be very difficult to troubleshoot.<\/p>\n<p>Most of the time, examining the values of variables does not solve the problem because the code itself works fine. The problem often lies in what are called &quot;the business rules&quot; of the script. These are decisions the code makes that have nothing to do with the correct operation of, for example, a switch statement. At times, it may appear that the switch statement is not working correctly because the wrong value is displayed at the end of the code. But quite often the business rules themselves are causing the problem.<\/p>\n<h2>The problem with logic errors<\/h2>\n<p>For a simple example of a logic error, consider the function called <b>My-function<\/b> that is shown here:<\/p>\n<p style=\"margin-left:30px\">My-Function.ps1<\/p>\n<p style=\"margin-left:30px\">Function my-function<\/p>\n<p style=\"margin-left:30px\">{<\/p>\n<p style=\"margin-left:30px\">&nbsp;Param(<\/p>\n<p style=\"margin-left:30px\">&nbsp; [int]$a,<\/p>\n<p style=\"margin-left:30px\">&nbsp; [int]$b)<\/p>\n<p style=\"margin-left:30px\">&nbsp; &quot;$a plus $b equals four&quot;<\/p>\n<p style=\"margin-left:30px\">}<\/p>\n<p>The <b>My-function<\/b> function accepts two command-line parameters: <b>a<\/b> and <b>b<\/b>. It then combines the two values and outputs a string that states the value is four. The tester performs four different tests, and each time the function performs as expected. These tests and the associated output are shown here:<\/p>\n<p style=\"margin-left:30px\">PS C:\\&gt; C:\\fso\\my-function.ps1<\/p>\n<p style=\"margin-left:30px\">PS C:\\&gt; my-function -a 2 -b 2<\/p>\n<p style=\"margin-left:30px\">&nbsp; 2 plus 2 equals four<\/p>\n<p style=\"margin-left:30px\">PS C:\\&gt; my-function -a 1 -b 3<\/p>\n<p style=\"margin-left:30px\">&nbsp; 1 plus 3 equals four<\/p>\n<p style=\"margin-left:30px\">PS C:\\&gt; my-function -a 0 -b 4<\/p>\n<p style=\"margin-left:30px\">&nbsp; 0 plus 4 equals four<span style=\"font-size:12px\">&nbsp;<\/span><\/p>\n<p style=\"margin-left:30px\">PS C:\\&gt; my-function -a 3 -b 1<\/p>\n<p style=\"margin-left:30px\">&nbsp; 3 plus 1 equals four<\/p>\n<p>When the function goes into production, however, users begin to complain. Most of the time, the function displays incorrect output. However, the users also report that no errors are generated when the function runs.<\/p>\n<p>What is the best way to solve the logic problem? Simply adding a couple of <b>Write-Debug<\/b> commands to display the values of the variables <b>a<\/b> and <b>b<\/b> will more than likely not lead to the correct solution. A better way is to step through the code one line at a time and examine the associated output. The easy way to do this is to use the <b>Set-PSDebug<\/b> cmdlet.<\/p>\n<h2>Using the Set-PSDebug cmdlet<\/h2>\n<p class=\"Normalunindented\">The <b>Set-PSDebug<\/b> cmdlet has been around since Windows PowerShell&nbsp;1.0. This does not mean it is a neglected feature, but rather, that it does what it needs to do. The <b>Set-PSDebug<\/b> cmdlet is not designed to do heavy debugging; it is a lightweight tool that is useful when you want to produce a quick trace or rapidly step through a script.<\/p>\n<p class=\"Normalunindented\">For performing basic debugging quickly and easily, you cannot beat the combination of features that are available. There are three things you can do with the <b>Set-PSDebug<\/b> cmdlet:<\/p>\n<ul>\n<li>Trace script execution in an automated fashion<\/li>\n<li>Step through the script interactively<\/li>\n<li>Enable strict mode to force good Windows PowerShell coding practices.<\/li>\n<\/ul>\n<p class=\"Normalunindented\"><span>Today, I&#039;ll begin to examine tracing the script&#8230;<\/span><\/p>\n<h2>Tracing the script<\/h2>\n<p class=\"Normalunindented\">One of the simplest ways to debug a script is to turn on script-level tracing. When you turn on script-level tracing, each command that is executed is displayed in the Windows PowerShell console. By watching the commands as they are displayed, you can determine if a line of code in your script executes or if it is being skipped.<\/p>\n<p class=\"Normalunindented\">To enable script tracing, you use the <b>Set-PSDebug<\/b> cmdlet and specify one of three levels for the <b>-trace<\/b> parameter:<\/p>\n<table border=\"0\" cellspacing=\"0\" cellpadding=\"0\">\n<tbody>\n<tr>\n<td width=\"108\" valign=\"bottom\">\n<p class=\"TableHead\">&nbsp; &nbsp; &nbsp;<strong>Trace level<\/strong><\/p>\n<\/td>\n<td width=\"432\" valign=\"bottom\">\n<p class=\"TableHead\"><strong>Meaning<\/strong><\/p>\n<\/td>\n<\/tr>\n<tr>\n<td width=\"108\" valign=\"top\">\n<p class=\"TableText\" align=\"center\">0<\/p>\n<\/td>\n<td width=\"432\" valign=\"top\">\n<p class=\"TableText\">Turns off script tracing.<\/p>\n<\/td>\n<\/tr>\n<tr>\n<td width=\"108\" valign=\"top\">\n<p class=\"TableText\" align=\"center\">1<\/p>\n<\/td>\n<td width=\"432\" valign=\"top\">\n<p class=\"TableText\">Traces each line of the script as it is executed. Lines in the script that are not executed are not traced. Does not display variable assignments, function calls, or external scripts.<\/p>\n<\/td>\n<\/tr>\n<tr>\n<td width=\"108\" valign=\"top\">\n<p class=\"TableText\" align=\"center\">2<\/p>\n<\/td>\n<td width=\"432\" valign=\"top\">\n<p class=\"TableText\">Traces each line of the script as it is executed. Lines in the script that are not executed are not traced. Displays variable assignments, function calls, and external scripts.<\/p>\n<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n<p>To understand the process of tracing a script and the differences between the trace levels, examine the CreateRegistryKey.ps1 script. It contains a single function called <b>Add-RegistryValue<\/b>. In the <b>Add-RegistryValue<\/b> function, the <b>Test-Path<\/b> cmdlet is used to determine if the registry key exists.<\/p>\n<p>If the registry key exists, a property value is set. If the registry key does not exist, the registry key is created and a property value is set. The <b>Add-RegistryValue<\/b> function is called when the script executes. The complete CreateRegistryKey.ps1 script is shown here:<\/p>\n<p class=\"CodeBlockHead\" style=\"margin-left:30px\">CreateRegistryKey.ps1<\/p>\n<p class=\"CodeBlock\" style=\"margin-left:30px\">Function Add-RegistryValue<br \/> {<br \/> &nbsp;Param ($key,$value)<br \/> &nbsp;$scriptRoot = &quot;HKCU:\\software\\ForScripting&quot;<br \/> &nbsp;if(-not (Test-Path -path $scriptRoot))<br \/> &nbsp;&nbsp; { <br \/> &nbsp;&nbsp;&nbsp; New-Item -Path HKCU:\\Software\\ForScripting | Out-Null <br \/> &nbsp;&nbsp;&nbsp; New-ItemProperty -Path $scriptRoot -Name $key -Value $value `<br \/> &nbsp;&nbsp;&nbsp; -PropertyType String | Out-Null<br \/> &nbsp;&nbsp;&nbsp; }<br \/> &nbsp; Else<br \/> &nbsp; {<br \/> &nbsp;&nbsp; Set-ItemProperty -Path $scriptRoot -Name $key -Value $value | `<br \/> &nbsp;&nbsp; Out-Null<br \/> &nbsp; }<br \/> &nbsp; <br \/> } #end function Add-RegistryValue<\/p>\n<p> # *** Entry Point to Script ***<br \/> Add-RegistryValue -key forscripting -value test<\/p>\n<h3>Working with trace level 1<\/h3>\n<p class=\"Normalunindented\">When the trace level is set to 1, each line in the script that executes is displayed to the Windows PowerShell console. To set the trace level to 1, you use the <b>Set-PSDebug<\/b><b><i> <\/i><\/b>cmdlet and assign a value of 1 to the <b>-trace<\/b> parameter.<\/p>\n<p>When the trace level has been set, it applies to everything that is typed in the Windows PowerShell console. If you run an interactive command, a cmdlet, or a script, it will be traced. When the CreateRegistryKey.ps1 script is run and there is no registry key present, the first debug line in the command displays the path to the script that is being executed.<\/p>\n<p>Because Windows PowerShell parses from the top down, the next line that is executed is the line that creates the <b>Add-RegistryValue<\/b> function. This command is on line 7 of the script because the actual script that executed contains six lines that are commented out.<\/p>\n<p>After the function is created, the next line of the script that executes is line 30. Line 30 of the CreateRegistryKey.ps1 script follows the comment that points to the entry point of the script (this is the last line), and it calls the <b>Add-RegistryValue<\/b> function by passing two values for the <b>-key<\/b> and <b>-value<\/b> parameters. This is shown here:<\/p>\n<p style=\"margin-left:30px\">PS C:\\&gt; Set-PSDebug -Trace 1<\/p>\n<p style=\"margin-left:30px\">PS C:\\&gt; C:\\fso\\CreateRegistryKey.ps1<\/p>\n<p style=\"margin-left:30px\">DEBUG:&nbsp;&nbsp;&nbsp; 1+&nbsp; &gt;&gt;&gt;&gt; C:\\fso\\CreateRegistryKey.ps1<\/p>\n<p style=\"margin-left:30px\">DEBUG:&nbsp;&nbsp; 30+&nbsp; &gt;&gt;&gt;&gt; Add-RegistryValue -key forscripting -value test<\/p>\n<p>After control of script execution is inside the <b>Add-RegistryValue<\/b> function, the <b>HKCU:\\software\\ForScripting<\/b> string is assigned to the <b>$scriptRoot<\/b> variable:<\/p>\n<p class=\"CodeBlock\" style=\"margin-left:30px\">DEBUG:&nbsp;&nbsp; 12+&nbsp; &gt;&gt;&gt;&gt; {<br \/> DEBUG:&nbsp;&nbsp; 14+&nbsp;&nbsp; &gt;&gt;&gt;&gt; $scriptRoot = &quot;HKCU:\\software\\ForScripting&quot;<\/p>\n<p>The <b>if<\/b><b><i> <\/i><\/b>statement is now evaluated. If the <b>Test-Path<\/b> cmdlet is unable to find the <b>$scriptRoot<\/b> location in the registry, the <b>if<\/b><b><i> <\/i><\/b>statement is entered, and the commands inside the associated script block will be executed.<\/p>\n<p>In this example, <b>$scriptRoot<\/b> is located, and the commands inside the script block are not executed:<\/p>\n<p class=\"CodeBlock\" style=\"margin-left:30px\">DEBUG:&nbsp;&nbsp; 15+&nbsp; if( &gt;&gt;&gt;&gt; -not (Test-Path -path $scriptRoot))<\/p>\n<p>As you see here, the <b>Set-ItemProperty<\/b> cmdlet is called on line 23 of the CreateRegistryKey.ps1 script:<\/p>\n<p style=\"margin-left:30px\">DEBUG:&nbsp;&nbsp; 23+&nbsp;&nbsp; &nbsp;&nbsp;&gt;&gt;&gt;&gt; Set-ItemProperty -Path $scriptRoot -Name $key -Value<\/p>\n<p style=\"margin-left:30px\">$value | `<\/p>\n<p>After the <b>Set-ItemProperty<\/b> cmdlet has executed, the script ends. The Windows PowerShell console parser now enters, with the same two lines of feedback that were shown when the tracing was first enabled:<\/p>\n<p style=\"margin-left:30px\">DEBUG:&nbsp;&nbsp; 27+&nbsp; &gt;&gt;&gt;&gt; } #end function Add-RegistryValue<\/p>\n<p style=\"margin-left:30px\">PS C:\\&gt;<\/p>\n<p>When you set the debug trace level to 1, a basic outline of the execution plan of the script is produced. This technique is good for quickly determining the outcome of branching statements (such as the <b>if<\/b><b><i> <\/i><\/b>statement) to see if a script block is being entered. This is shown here.<\/p>\n<p><a href=\"https:\/\/devblogs.microsoft.com\/wp-content\/uploads\/sites\/29\/2019\/02\/1462.1.png\"><img decoding=\"async\" src=\"https:\/\/devblogs.microsoft.com\/wp-content\/uploads\/sites\/29\/2019\/02\/1462.1.png\" alt=\"Image of command output\" title=\"Image of command output\" \/><\/a><\/p>\n<p>DR, that is all there is to using script tracing to help debug a script. Debugging Week will continue tomorrow when I will talk about working with trace level 2.<\/p>\n<p>I invite you to follow me on <a href=\"http:\/\/bit.ly\/scriptingguystwitter\" target=\"_blank\">Twitter<\/a> and <a href=\"http:\/\/bit.ly\/scriptingguysfacebook\" target=\"_blank\">Facebook<\/a>. If you have any questions, send email to me at <a href=\"mailto:scripter@microsoft.com\" target=\"_blank\">scripter@microsoft.com<\/a>, or post your questions on the <a href=\"http:\/\/bit.ly\/scriptingforum\" target=\"_blank\">Official Scripting Guys Forum<\/a>. See you tomorrow. Until then, peace.<\/p>\n<p><b>Ed Wilson, Microsoft Scripting Guy<\/b><\/p>\n","protected":false},"excerpt":{"rendered":"<p>Summary: Ed Wilson, Microsoft Scripting Guy, talks about using a cmdlet to trace the execution of a Windows PowerShell script. &nbsp;Hey, Scripting Guy! I am having a problem with a script. It does not generate any errors, but dude, it does not seem to work either. Can you help me debug it? &mdash;DR &nbsp;Hello DR, [&hellip;]<\/p>\n","protected":false},"author":596,"featured_media":87096,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"_acf_changed":false,"footnotes":""},"categories":[1],"tags":[294,3,4,45],"class_list":["post-72192","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-scripting","tag-debugging","tag-scripting-guy","tag-scripting-techniques","tag-windows-powershell"],"acf":[],"blog_post_summary":"<p>Summary: Ed Wilson, Microsoft Scripting Guy, talks about using a cmdlet to trace the execution of a Windows PowerShell script. &nbsp;Hey, Scripting Guy! I am having a problem with a script. It does not generate any errors, but dude, it does not seem to work either. Can you help me debug it? &mdash;DR &nbsp;Hello DR, [&hellip;]<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/posts\/72192","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/users\/596"}],"replies":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/comments?post=72192"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/posts\/72192\/revisions"}],"wp:featuredmedia":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/media\/87096"}],"wp:attachment":[{"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/media?parent=72192"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/categories?post=72192"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/tags?post=72192"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}