Why does PowerShell chops message on stderr?

Question

I'm using a PowerShell script to control different compilation steps of an compiler (ghdl.exe).

The compiler has 3 different output formats:

1. No output and no error => $LastExitCode = 0
2. outputs on stderr (warnings), but no errors => $LastExitCode = 0
3. outputs on stderr (errors), and maybe warnings => $LastExitCode != 0

Because handling of stderr and stdout seams to be very buggy, I used the method presented in this StackOverflow post: PowerShell: Manage errors with Invoke-Expression

Here is my implementation with addition message coloring:

function Format-NativeCommandStreams
{ param([Parameter(ValueFromPipeline=$true)]$InputObject)

  begin
  { $ErrorRecordFound = $false  }

  process
  { if (-not $InputObject)
    { Write-Host "Empty"  }
    elseif ($InputObject -is [System.Management.Automation.ErrorRecord])
    { $ErrorRecordFound  = $true
      $text = $InputObject.ToString()
      Write-Host $text -ForegroundColor  Gray

      $stdErr = $InputObject.TargetObject
      if ($stdErr)
      { #Write-Host ("err: type=" + $stdErr.GetType() + "  " + $stdErr)
        if ($stdErr.Contains("warning"))
        { Write-Host "WARNING: "  -NoNewline -ForegroundColor Yellow  }
        else
        { Write-Host "ERROR: "    -NoNewline -ForegroundColor Red      }
        Write-Host $stdErr
      }
    }
    else
    { $stdOut = $InputObject                
      if ($stdOut.Contains("warning"))
      { Write-Host "WARNING: "  -NoNewline -ForegroundColor Yellow  }
      else
      { Write-Host "ERROR: "    -NoNewline -ForegroundColor Red      }
      Write-Host $stdOut
    }
  }

  end
  { $ErrorRecordFound    }
}

Usage:

$Options = @(.....)
$Expr = "ghdl.exe -a " + ($Options -join " ") + " " + $File + " 2>&1"
$ret = Invoke-Expression $Expr | Format-NativeCommandStreams

Normally, the compiler emits one message (error or warning) per line. As shown in the screenshot below, some messages got chopped in up to 8 lines. That's the reason why my output coloring does not work as expected. More over some lines are detected as errors (false positives), so I can't find the real error in the logs.

(clickable)

Example:

C:\Altera\15.0\quartus\eda\sim_lib\altera_mf.vhd:
39963:
53
:
warning:

universal integer bound must be numeric literal or attribute

C:\Altera\15.0\quartus\eda\sim_lib\altera_mf.vhd
:41794:36:warning: universal integer bound must be numeric literal or attribute

Expected Result:

C:\Altera\15.0\quartus\eda\sim_lib\altera_mf.vhd:39963:53:warning: universal integer bound must be numeric literal or attribute
C:\Altera\15.0\quartus\eda\sim_lib\altera_mf.vhd:41794:36:warning: universal integer bound must be numeric literal or attribute

As far as I can see, the compiler (ghdl.exe) does emit the messages as full lines.

Questions:

• Why does this happen?
• Who can I solve this?

Thirtieth

Sorry I forgot the calling lines. I'll add them when I'm back to my computer. – Thirtieth

Answer 1

Solution

The complete output on stderr of the executable is simply split across several objects of type System.Management.Automation.ErrorRecord. The actual splitting seems to be non deterministic (*). Moreover, the partial strings are stored inside the property Exception instead of TargetObject. Only the first ErrorRecord has a non-null TargetObject. That is, why subsequent lines of your output containing the string "warning" are not formatted in yellow and white, like this one:

:41794:36:warning: universal integer bound must be numeric literal or attribute

Your grey output comes from the toString() method of each ErrorRecord which returns the value of the property Exception.Message of this record. So one must concatenate all messages together to get the whole output before formatting it. Newlines are preserved in these messages.

EDIT: (*) It depends on the order of write/flush calls of the program in relation to the read calls of the Powershell. If one adds a fflush(stderr) after each fprintf() in my test program below, there will be much more ErrorRecord objects. Except the first one, which seems deterministic, some of them include 2 output lines and some of them 3.

My testbench

Instead of using GHDL I started with a new Visual Studio project and created a console application (HelloWorldEx) with the following code. It simply prints out a lot of numbered lines on stderr

#include "stdafx.h"
#include <stdio.h>

int _tmain(int argc, _TCHAR* argv[])
{
  // Print some warning messages on stderr
  for(int i=0; i<70; i++) {
    fprintf(stderr, "warning:%070d\n", i); // 80 bytes per line including CR+LF
  }
  return 0; // exit code is not relevant
}

Then I compiled the program and executed it inside the Powershell with: (EDIT: removed debug code from my own script)

.\HelloWorldEx.exe 2>&1 | set-variable Output
$i = 0
$Output | % {
  Write-Host ("--- " + $i + ": "  + $_.GetType() +  " ------------------------")
  Write-Host ($_ | Format-List -Force | Out-String)
  $i++
}

This was the output of the script. As you can see, the output of my program is split accross 3 ErrorRecords (the actual might differ):

--- 0: System.Management.Automation.ErrorRecord ------------------------


writeErrorStream      : True
Exception             : System.Management.Automation.RemoteException: warning:00000000000000000000000000000000000000000
                        00000000000000000000000000000
TargetObject          : warning:0000000000000000000000000000000000000000000000000000000000000000000000
CategoryInfo          : NotSpecified: (warning:0000000...000000000000000:String) [], RemoteException
FullyQualifiedErrorId : NativeCommandError
ErrorDetails          : 
InvocationInfo        : System.Management.Automation.InvocationInfo
PipelineIterationInfo : {0, 0, 0}
PSMessageDetails      : 




--- 1: System.Management.Automation.ErrorRecord ------------------------


writeErrorStream      : True
Exception             : System.Management.Automation.RemoteException: warning:00000000000000000000000000000000000000000
                        00000000000000000000000000001
                        warning:0000000000000000000000000000000000000000000000000000000000000000000002
                        warning:0000000000000000000000000000000000000000000000000000000000000000000003
                        warning:0000000000000000000000000000000000000000000000000000000000000000000004
                        warning:0000000000000000000000000000000000000000000000000000000000000000000005
                        warning:0000000000000000000000000000000000000000000000000000000000000000000006
                        warning:0000000000000000000000000000000000000000000000000000000000000000000007
                        warning:0000000000000000000000000000000000000000000000000000000000000000000008
                        warning:0000000000000000000000000000000000000000000000000000000000000000000009
                        warning:0000000000000000000000000000000000000000000000000000000000000000000010
                        warning:0000000000000000000000000000000000000000000000000000000000000000000011
                        warning:0000000000000000000000000000000000000000000000000000000000000000000012
                        warning:0000000000000000000000000000000000000000000000000000000000000000000013
                        warning:0000000000000000000000000000000000000000000000000000000000000000000014
                        warning:0000000000000000000000000000000000000000000000000000000000000000000015
                        warning:0000000000000000000000000000000000000000000000000000000000000000000016
                        warning:0000000000000000000000000000000000000000000000000000000000000000000017
                        warning:0000000000000000000000000000000000000000000000000000000000000000000018
                        warning:0000000000000000000000000000000000000000000000000000000000000000000019
                        warning:0000000000000000000000000000000000000000000000000000000000000000000020
                        warning:0000000000000000000000000000000000000000000000000000000000000000000021
                        warning:0000000000000000000000000000000000000000000000000000000000000000000022
                        warning:0000000000000000000000000000000000000000000000000000000000000000000023
                        warning:0000000000000000000000000000000000000000000000000000000000000000000024
                        warning:0000000000000000000000000000000000000000000000000000000000000000000025
                        warning:0000000000000000000000000000000000000000000000000000000000000000000026
                        warning:0000000000000000000000000000000000000000000000000000000000000000000027
                        warning:0000000000000000000000000000000000000000000000000000000000000000000028
                        warning:0000000000000000000000000000000000000000000000000000000000000000000029
                        warning:0000000000000000000000000000000000000000000000000000000000000000000030
                        warning:0000000000000000000000000000000000000000000000000000000000000000000031
                        warning:0000000000000000000000000000000000000000000000000000000000000000000032
                        warning:0000000000000000000000000000000000000000000000000000000000000000000033
                        warning:0000000000000000000000000000000000000000000000000000000000000000000034
                        warning:0000000000000000000000000000000000000000000000000000000000000000000035
                        warning:0000000000000000000000000000000000000000000000000000000000000000000036
                        warning:0000000000000000000000000000000000000000000000000000000000000000000037
                        warning:0000000000000000000000000000000000000000000000000000000000000000000038
                        warning:0000000000000000000000000000000000000000000000000000000000000000000039
                        warning:0000000000000000000000000000000000000000000000000000000000000000000040
                        warning:0000000000000000000000000000000000000000000000000000000000000000000041
                        warning:0000000000000000000000000000000000000000000000000000000000000000000042
                        warning:0000000000000000000000000000000000000000000000000000000000000000000043
                        warning:0000000000000000000000000000000000000000000000000000000000000000000044
                        warning:0000000000000000000000000000000000000000000000000000000000000000000045
                        warning:0000000000000000000000000000000000000000000000000000000000000000000046
                        warning:0000000000000000000000000000000000000000000000000000000000000000000047
                        warning:0000000000000000000000000000000000000000000000000000000000000000000048
                        warning:0000000000000000000000000000000000000000000000000000000000000000000049
                        warning:0000000000000000000000000000000000000000000000000000000000000000000050
                        warning:00000000000000000000000000000000000000000000000000000000000
TargetObject          : 
CategoryInfo          : NotSpecified: (:) [], RemoteException
FullyQualifiedErrorId : NativeCommandErrorMessage
ErrorDetails          : 
InvocationInfo        : System.Management.Automation.InvocationInfo
PipelineIterationInfo : {0, 0, 1}
PSMessageDetails      : 




--- 2: System.Management.Automation.ErrorRecord ------------------------


writeErrorStream      : True
Exception             : System.Management.Automation.RemoteException: 00000000051
                        warning:0000000000000000000000000000000000000000000000000000000000000000000052
                        warning:0000000000000000000000000000000000000000000000000000000000000000000053
                        warning:0000000000000000000000000000000000000000000000000000000000000000000054
                        warning:0000000000000000000000000000000000000000000000000000000000000000000055
                        warning:0000000000000000000000000000000000000000000000000000000000000000000056
                        warning:0000000000000000000000000000000000000000000000000000000000000000000057
                        warning:0000000000000000000000000000000000000000000000000000000000000000000058
                        warning:0000000000000000000000000000000000000000000000000000000000000000000059
                        warning:0000000000000000000000000000000000000000000000000000000000000000000060
                        warning:0000000000000000000000000000000000000000000000000000000000000000000061
                        warning:0000000000000000000000000000000000000000000000000000000000000000000062
                        warning:0000000000000000000000000000000000000000000000000000000000000000000063
                        warning:0000000000000000000000000000000000000000000000000000000000000000000064
                        warning:0000000000000000000000000000000000000000000000000000000000000000000065
                        warning:0000000000000000000000000000000000000000000000000000000000000000000066
                        warning:0000000000000000000000000000000000000000000000000000000000000000000067
                        warning:0000000000000000000000000000000000000000000000000000000000000000000068
                        warning:0000000000000000000000000000000000000000000000000000000000000000000069

TargetObject          : 
CategoryInfo          : NotSpecified: (:) [], RemoteException
FullyQualifiedErrorId : NativeCommandErrorMessage
ErrorDetails          : 
InvocationInfo        : System.Management.Automation.InvocationInfo
PipelineIterationInfo : {0, 0, 2}
PSMessageDetails      : 

Gallant

The actual splitting seems to be undefined. It is not totally undefined. First line will be in the first ErrorRecord with FullyQualifiedErrorId: NativeCommandError, new line character not preserved here. The rest of error stream will be splitted between rest of ErrorRecords with FullyQualifiedErrorId: NativeCommandErrorMessage. If you add explicit flushing into you program, then you likely notice, that splitting happens by flush points. – Sinuosity

@PetSerAl I have tried fflush(stderr) after each line, but it is still undefined. Now some times 2 lines and some times 3 lines are included in one ErrorRecord. Only the first one is deterministic. Plese note, that my program is only a demonstrator. The output of GHDL is split up more often even within one line according to the screenshot. – Gallant

I does not say, that it will split on every flush point. PowerShell simply try to read as much as it can (up to buffer size, of course) and write ErrorRecord with read string. If program happens to make multiple flushes before PowerShell make new read call, then content of that multiple flushes will be read. Actual results depends on many factor, so I would call it nondeterministic. The output of GHDL is split up more often even within one line according to the screenshot. Apparently, it flush multiple times per line, so that cause line chopping. – Sinuosity

This only works correctly for Powershell ISE. Powershell.exe doesn't need this. See my comment. – Soares

Answer 2

You can a bit of debugging to sort this out. I suggest starting with something like this:

ghdl.exe <whatever args you supply> 2>&1 | set-variable ghdlOutput
$i = 0
$ghdlOutput | % {write-host "$i `t: " $_.gettype() "`t" $_ ; $i++}

This will list the line number, type of the output line, and each live of the output. You may have to tweak the code some to get the output to look OK.

From there you can see if the compiler is really splitting up errors into multiple lines. If it is you can try devise a strategy for determining which lines are stdout and which are stderr. If not, then you'll have some clues to debugging your script above.

Or can bag this whole approach and use the .NET system.diagnostics.process class and redirect stdout and stderr as separate streams. Use the Start method that takes a ProcessStartInfo. You should be able to google examples of doing this if you need to.

Armandinaarmando

Answer 3

Just for completeness, here are my current CommandLets, which restore the error messages as a single line and color them as wanted:

Usage:

$InvokeExpr = "ghdl.exe " + ($Options -join " ") + " --work=unisim " + $File.FullName + " 2>&1"
$ErrorRecordFound = Invoke-Expression $InvokeExpr | Collect-NativeCommandStream | Write-ColoredGHDLLine

CommandLet to restore the error messages:

function Collect-NativeCommandStream
{ [CmdletBinding()]
  param([Parameter(ValueFromPipeline=$true)]$InputObject)

  begin
  { $LineRemainer = ""  }

  process
  { if (-not $InputObject)
    { Write-Host "Empty pipeline!"  }
    elseif ($InputObject -is [System.Management.Automation.ErrorRecord])
    { if ($InputObject.FullyQualifiedErrorId -eq "NativeCommandError")
      { Write-Output $InputObject.ToString()    }
      elseif ($InputObject.FullyQualifiedErrorId -eq "NativeCommandErrorMessage")
      { $NewLine = $LineRemainer + $InputObject.ToString()
        while (($NewLinePos = $NewLine.IndexOf("`n")) -ne -1)
        { Write-Output $NewLine.Substring(0, $NewLinePos)
          $NewLine = $NewLine.Substring($NewLinePos + 1)
        }
        $LineRemainer = $NewLine
      }
    }
    elseif ($InputObject -is [String])
    { Write-Output $InputObject    }
    else
    { Write-Host "Unsupported object in pipeline stream"    }
  }

  end
  {   }
}

CommandLet to color warnings and errors:

function Write-ColoredGHDLLine
{ [CmdletBinding()]
  param([Parameter(ValueFromPipeline=$true)]$InputObject)

  begin
  { $ErrorRecordFound = $false  }

  process
  { if (-not $InputObject)
    { Write-Host "Empty pipeline!"  }
    elseif ($InputObject -is [String])
    { if ($InputObject.Contains("warning"))
      { Write-Host "WARNING: "  -NoNewline -ForegroundColor Yellow  }
      else
      { $ErrorRecordFound  = $true
        Write-Host "ERROR: "    -NoNewline -ForegroundColor Red
      }
      Write-Host $InputObject
    }
    else
    { Write-Host "Unsupported object in pipeline stream"    }
  }

  end
  { $ErrorRecordFound    }
}

Thirtieth

Answer 4

It seems that I managed to solve the problem with Martin Zabel example and the solution turned out to be quite prosaic and simple.

The fact is that for a long time I could not get the characters `r`n from an incoming call. And it turned out to be simple.

Replacing the `r with `n is the only thing that needed to be done at all!

The solution will work correctly for any width of the console, because the reverses have been removed.

Also, this may be the basis for solving the problem of returning processed data to the console in real time. The only thing that is needed is to catch the incoming single `r or `n to get a new "variable-string" in and send the processed data back to the console with `r or `n, depending on the task .

cls
function GetAnsVal {
    param([Parameter(Mandatory=$true, ValueFromPipeline=$true)][System.Object[]][AllowEmptyString()]$Output,
          [Parameter(Mandatory=$false, ValueFromPipeline=$true)][System.String]$firstEncNew="UTF-8",
          [Parameter(Mandatory=$false, ValueFromPipeline=$true)][System.String]$secondEncNew="CP866"
    )
    function ConvertTo-Encoding ([string]$From, [string]$To){#"UTF-8" "CP866" "ASCII" "windows-1251"
        Begin{
            $encFrom = [System.Text.Encoding]::GetEncoding($from)
            $encTo = [System.Text.Encoding]::GetEncoding($to)
        }
        Process{
            $Text=($_).ToString()
            $bytes = $encTo.GetBytes($Text)
            $bytes = [System.Text.Encoding]::Convert($encFrom, $encTo, $bytes)
            $encTo.GetString($bytes)
        }
    }
    $all = New-Object System.Collections.Generic.List[System.Object];
    $exception = New-Object System.Collections.Generic.List[System.Object];
    $stderr = New-Object System.Collections.Generic.List[System.Object];
    $stdout = New-Object System.Collections.Generic.List[System.Object]
    $i = 0;$Output | % {
        if ($_ -ne $null){
            if ($_.GetType().FullName -ne 'System.Management.Automation.ErrorRecord'){
                if ($_.Exception.message -ne $null){$Temp=$_.Exception.message | ConvertTo-Encoding $firstEncNew $secondEncNew;$all.Add($Temp);$exception.Add($Temp)}
                elseif ($_ -ne $null){$Temp=$_ | ConvertTo-Encoding $firstEncNew $secondEncNew;$all.Add($Temp);$stdout.Add($Temp)}
            } else {
                #if (MyNonTerminatingError.Exception is AccessDeniedException)
                $Temp=$_.Exception.message | ConvertTo-Encoding $firstEncNew $secondEncNew;
                $all.Add($Temp);$stderr.Add($Temp)
            }   
         }
    $i++
    }
    [hashtable]$return = @{}
    $return.Meta0=$all;$return.Meta1=$exception;$return.Meta2=$stderr;$return.Meta3=$stdout;
    return $return
}
Add-Type -AssemblyName System.Windows.Forms;
& C:\Windows\System32\curl.exe 'api.ipify.org/?format=plain' 2>&1 | set-variable Output;
$r = & GetAnsVal $Output
$Meta0=""
foreach ($el in $r.Meta0){
    $Meta0+=$el
}
$Meta0=($Meta0 -split "[`r`n]") -join "`n"
$Meta0=($Meta0 -split "[`n]{2,}") -join "`n"
[Console]::Write($Meta0);
[Console]::Write("`n");

Soares