Unexpected line space in Verbose output

This topic contains 4 replies, has 2 voices, and was last updated by  Kevyn 2 weeks, 2 days ago.

  • Author
    Posts
  • #76522

    Kevyn
    Participant

    I've got the below script that I'm testing on my machine (Prometheus). I am pipelining 3 machine names into the Get-VolumeInfo function. Localhost is Prometheus, so I'm just getting the same volume information (2 volumes on the machine) twice from the same machine. I then have a fake machine name called Gotcha just to test the error capturing of the script. When I run the function with the -Verbose parameter, there is an unexpected blank line just after the first volume of the first computer name (i.e. localhost). See the output I get below the script code. It doesn't happen when processing the volume information when the name Prometheus is passed to the function. Any idea why and how I can get rid of the blank line?

    Function Get-VolumeInfo
    {
      [CmdletBinding()]
      Param
      (
        [Parameter(Mandatory=$true,
                   ValueFromPipeline = $True,
                   HelpMessage = "Enter computer names, one a time.  Hit the Enter key twice after typing in the last computer name.  Or, re-run the script and put in a comma-separated listed after the -ComputerName parameter.")]
        [ValidateNotNullOrEmpty()]
        [string[]] $ComputerName,
    
        [string] $ErrorFile = 'C:\Data\Errors.txt',
    
        [switch] $LogErrors
      )
    
      Begin
      {
        Write-Verbose "Starting Get-VolumeInfo."
      } #End Begin block
      Process
      {
        ForEach($Computer in $ComputerName)
        {
          Try
          {
            Write-Verbose "Getting Win32_Volume data from: $Computer"
            $Volumes = Get-WmiObject -Class Win32_Volume -ComputerName $Computer -Filter "DriveType = 3" -ErrorAction Stop       
          } #End Try block
          Catch
          {
            If($LogErrors)
            {
              Write-Verbose "Failed to get Win32_Volume information.  See $ErrorFile for further information."
              $ErrMsgCS = "$(Get-Date): [ERROR]: Failed to get the Win32_Volume information from $Computer.  Error message was: $($_.Exception.Message)"
              $ErrMsgCS | Out-File -FilePath $ErrorFile -Append
            }
            Else
            {
              Write-Verbose "Failed to get Win32_Volume information.  To log the error details, re-run the script with the -LogErrors parameter."
            }
          } #End Catch block
    
          If($Volumes)
          {
            ForEach($Volume in $Volumes)
            {
              Write-Verbose "Processing volume: $($Volume.Name)"
              $VolumeProps = @{
                                ComputerName = $Volume.SystemName;
                                Drive = $Volume.Name;
                                'FreeSpace (GB)' = "{0:N2}" -f ($Volume.FreeSpace / 1GB);
                                'Size (GB)' = "{0:N2}" -f ($Volume.Capacity / 1GB)
                              }
              New-Object -TypeName PSObject -Property $VolumeProps
            } #End ForEach block
          } #End If block
          Remove-Variable -Name 'Volumes' -ErrorAction SilentlyContinue
        } #End ForEach block
      } # End Process block
      End
      {
        Write-Verbose "Ending Get-VolumeInfo."
      } #End End block
    } #End Function block
    
    'localhost','prometheus','gotcha' | Get-VolumeInfo -Verbose -LogErrors
    

    Here is the output I get.

    VERBOSE: Starting Get-VolumeInfo.
    VERBOSE: Getting Win32_Volume data from: localhost
    VERBOSE: Processing volume: C:\
    —-Unexpected blank line —-
    VERBOSE: Processing volume: \\?\Volume{463fb708-9f47-410b-9051-d8ddaf9ae75b}\
    VERBOSE: Getting Win32_Volume data from: prometheus
    VERBOSE: Processing volume: C:\
    VERBOSE: Processing volume: \\?\Volume{463fb708-9f47-410b-9051-d8ddaf9ae75b}\
    VERBOSE: Getting Win32_Volume data from: gotcha
    VERBOSE: Failed to get Win32_Volume information. See C:\Data\Errors.txt for further information.
    VERBOSE: Ending Get-VolumeInfo.

    Drive ComputerName FreeSpace (GB) Size (GB)
    —– ———— ————– ———
    C:\ PROMETHEUS 41.71 237.20
    \\?\Volume{463fb708-9f47-410b-9051-d8ddaf9ae75b}\ PROMETHEUS 0.53 0.90
    C:\ PROMETHEUS 41.71 237.20
    \\?\Volume{463fb708-9f47-410b-9051-d8ddaf9ae75b}\ PROMETHEUS 0.53 0.90

  • #76532

    Curtis Smith
    Participant

    The issues is that the first object is getting sent down the pipeline and getting to the default output. When the first object gets to default output, a blank line is written to the console and this shows up in the VERBOSE area as you are seeing it.

    If you put something after the Get-VolumeInfo function that will keep the Output from reaching the console until all object are gathered, then the blank line is not written to the console in the verbose area. Instead it appears after the Ending Get-VolumeInfo because the first object does not hit output until after the function is complete.

    IE

    'localhost','prometheus','gotcha' | Get-VolumeInfo -Verbose -LogErrors | Sort
  • #76572

    Kevyn
    Participant

    Thanks, Curtis. That makes sense, and the solution worked. One question (really two), though. Why does the first object get sent down the pipeline to Out-Default before the other objects are ready?...And why does this occur just on the first object?

  • #76590

    Curtis Smith
    Participant

    Question 1: Why does the first object get sent down the pipeline to Out-Default before the other objects are ready?

    Well, for the why, I would just have to say that it's how Microsoft made it. I can't really say why they did it this way, I can really only prove that this is how it works.

    IE.

    1,2,3 | Select-Object @{l='Item';e={$_}}, @{l='P1';e={start-sleep 1; get-date}} | Select-Object *, @{l='P2';e={start-sleep 2; get-date}} | Select-Object *, @{l='P3';e={start-sleep 3; get-date}}

    Results:

    Item P1                  P2                  P3                 
    ---- --                  --                  --                 
       1 8/3/2017 9:57:07 AM 8/3/2017 9:57:09 AM 8/3/2017 9:57:12 AM
       2 8/3/2017 9:57:13 AM 8/3/2017 9:57:15 AM 8/3/2017 9:57:18 AM
       3 8/3/2017 9:57:19 AM 8/3/2017 9:57:21 AM 8/3/2017 9:57:24 AM

    As you can see from the above table, Item 1 is sent down the pipeline and it's time stamped as passing through each position in the pipeline before Item 2 begins it's journey down the pipeline. They do not run in parallel. Likewise, Item 3 does not begin it's journey down the pipeline until Item 2 has completed it's journey.

    Question 2: And why does this occur just on the first object?
    Again I would have to say because this is how Microsoft made it. Without having access to the code of Out-Default and/or Format-Table/Format-List, I cannot say for certain what part of the code is doing it, but I can show the behavior. In actuality, it's not Out-Default that adds the blank line. It's the Format- that does it. Out-Default really only sends the data to Format-Table or Format-List based on the input. Format-Table is what sends the blank line and then waits to get the rest of the objects so that it can adjust for column width and such before sending the output to the console. Format-List also sends the blank line, but does not wait for the rest of the content.

    IE.
    If the number of properties in the object is less than 5, then Out-Default will use Format-Table to format the output to the console.

    "---------------" | Out-Host
    [pscustomobject]@{item1 = 'value1';item2 = 'value1';item3 = 'value1';item4 = 'value1'}
    [pscustomobject]@{item1 = 'value2';item2 = 'value2';item3 = 'value2';item4 = 'value2'}
    [pscustomobject]@{item1 = 'value3';item2 = 'value3';item3 = 'value3';item4 = 'value3'}
    "---------------" | Out-Host

    Results:

    ---------------
    
    ---------------
    item1  item2  item3  item4 
    -----  -----  -----  ----- 
    value1 value1 value1 value1
    value2 value2 value2 value2
    value3 value3 value3 value3

    Notice how the blank line is between the "---------------" lines. This is because the blank line was output to the console when the first object arrived at Format-Table, but Format-Table held on to the objects until it received them all, and output them together in a table at the end.

    If we instruct powershell to send each object out to default immediately, you can see the blank lines being inserted before and after each table, and because we are sending to Out-Default immediately, the output shows up between the "---------------" instead of being held and gathered together at the end.

    IE

    "---------------" | Out-Host
    [pscustomobject]@{item1 = 'value1';item2 = 'value1';item3 = 'value1';item4 = 'value1'} | Out-Default
    [pscustomobject]@{item1 = 'value2';item2 = 'value2';item3 = 'value2';item4 = 'value2'} | Out-Default
    [pscustomobject]@{item1 = 'value3';item2 = 'value3';item3 = 'value3';item4 = 'value3'} | Out-Default
    "---------------" | Out-Host

    Results:

    ---------------
    
    item1  item2  item3  item4 
    -----  -----  -----  ----- 
    value1 value1 value1 value1
    
    
    
    item1  item2  item3  item4 
    -----  -----  -----  ----- 
    value2 value2 value2 value2
    
    
    
    item1  item2  item3  item4 
    -----  -----  -----  ----- 
    value3 value3 value3 value3
    
    
    ---------------

    If the number of properties in the object is 5 or more, then Out-Default will use Format-List to format the output to the console.

    "---------------" | Out-Host
    [pscustomobject]@{item1 = 'value1';item2 = 'value1';item3 = 'value1';item4 = 'value1';item5 = 'value1'}
    [pscustomobject]@{item1 = 'value2';item2 = 'value2';item3 = 'value2';item4 = 'value2';item5 = 'value2'}
    [pscustomobject]@{item1 = 'value3';item2 = 'value3';item3 = 'value3';item4 = 'value3';item5 = 'value3'}
    "---------------" | Out-Host

    Results:

    ---------------
    
    
    item1 : value1
    item2 : value1
    item3 : value1
    item4 : value1
    item5 : value1
    
    item1 : value2
    item2 : value2
    item3 : value2
    item4 : value2
    item5 : value2
    
    item1 : value3
    item2 : value3
    item3 : value3
    item4 : value3
    item5 : value3
    
    ---------------

    Notices this time that there is a blank line inserted, 1 before the list, 1 before each object, and 1 after the list; however, since Format-List does not hold onto the object to do any additional calculation for things like column width, you see the output actually shows up in between the "---------------" lines.

    Hope this helps.

  • #76596

    Kevyn
    Participant

    Thanks Curtis for the detailed explanation & examples. It really helped. That was awesome of you to take the time.

You must be logged in to reply to this topic.