Tracking down commands that are polluting your pipeline

This is a PowerShell “gotcha” that has probably caught every one of us at some point or another: You are writing a function… it’s intended to output a certain type of object, perhaps even a single value such as $true or $false in a Test- function, and you run it. You get a bunch of random garbage output, because some of the commands in your function are generating output that you forgot to suppress (or just didn’t know about). For example:

function Test-Function
{
    $arrayList = New-Object System.Collections.ArrayList

    $null = $arrayList.Add('One')
    [void] $arrayList.Add('Two')
    $arrayList.Add('Three') | Out-Null
    
    $arrayList.Add('Four')

    return $true
}

I’ll pick on ArrayList today, since its Add method returns an integer result which you may or may not actually care about. I suppressed the output from the first three calls to $arrayList.Add() using three different methods: assigning the result to a variable (or to $null if you just want to discard it), casting the result to [void], and piping the result to Out-Null. All three are valid, though the pipe to Out-Null is noticeably slower, if you’re doing this in a loop a few thousand times.

The fourth call, however, produces an integer result which is allowed to be written to the Output stream of the function. If you run this function as-is, it will write both “3” and $true to the output stream, instead of just the $true value you had intended.

Now, this is a small function, where it’s easy to spot the error. Ideally, all functions would look like this: neat and tidy, easy to debug. Unfortunately, this is often not the case. You may have written a function that grew quite large and hasn’t been refactored yet, or you may be inheriting and debugging someone else’s code. In the past, I’ve given the code a look over first, to see if I can spot the problem. If not, I would step through it in the ISE, hitting F11 until something unexpected showed up in the console window.

Today, someone asked about this topic on the TechNet forums, and for whatever reason, said debugging the script wasn’t going to be a viable option for him, so I started looking for a quicker, automated way to get this debugging done, and found that by piping the output of the command you want to debug into a function which looks at Get-PSCallStack, we can identify the culprits pretty quick (at least on PowerShell 3.0 or later; the Get-PSCallStack cmdlet doesn’t provide quite a useful information in version 2.0.) I tweaked the test function slightly to call on both another function, and another PowerShell script, and piped the output to this Get-OutputProducingCommand filter:

filter Get-OutputProducingCommand
{
    $output = New-Object System.Text.StringBuilder

    $stack = @(Get-PSCallStack)
    $indent = 0

    # Ignoring the top level or two of the call stack, where we've invoked the script.
    # This behavior is slightly different depending on whether the script was run at
    # a prompt, or executed by the ISE with F5.  We also ignore the stack entry at index
    # 0, which will always be the Get-OutputProducingCommand filter itself.

    $startIndex = $stack.Count - 1
    if (('<No file>', 'prompt') -contains $stack[$startIndex].Location) { $startIndex-- }

    for ($i = $startIndex - 1; $i -gt 0; $i--)
    {
        $null = $output.AppendFormat("{0,$indent}{1} ({2} Line {3}): {4}`r`n",
                                     [string]::Empty,
                                     $stack[$i].Command,
                                     (Split-Path -Path $stack[$i].ScriptName -Leaf),
                                     $stack[$i].ScriptLineNumber,
                                     $stack[$i].Position.Text)          
        $indent += 2
    }

    $output.ToString()
}

function Test-Function
{
    $arrayList = New-Object System.Collections.ArrayList

    $null = $arrayList.Add('One')
    [void] $arrayList.Add('Two')
    $arrayList.Add('Three') | Out-Null
    
    $arrayList.Add('Four')

    Test-NestedFunction

    # testNestedScript.ps1 is just a one-liner that returns a string,
    # to make sure this code displays useful output when calling into
    # an external script file instead of just calling a function.
    
    .\testNestedScript.ps1

    return $true
}

function Test-NestedFunction
{
    Write-Output 5
}

Test-Function |
Get-OutputProducingCommand

By piping our offending function Test-Function to Get-OutputProducingCommand, we get the following result. It’s a fairly quick and painless way to narrow down the search for those unruly commands that are sending junk down the pipeline.

Test-Function (Test.ps1 Line 9): $arrayList.Add('Four')

Test-Function (Test.ps1 Line 11): Test-NestedFunction
  Test-NestedFunction (Test.ps1 Line 20): Write-Output 5

Test-Function (Test.ps1 Line 13): .\testNestedScript.ps1
  testNestedScript.ps1 (testNestedScript.ps1 Line 1): 'This is a test!'

Test-Function (Test.ps1 Line 15): $true
Advertisements

About Dave Wyatt

Microsoft MVP (PowerShell), IT professional.
This entry was posted in PowerShell. Bookmark the permalink.

One Response to Tracking down commands that are polluting your pipeline

  1. Pingback: Tracking down commands that are polluting your pipeline | PowerShell.org

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