choco.exe: write to stderr and stdout

[sergey-s-betke]

What You Are Seeing?

choco.exe does not write to stdout and stderr:

choco 0.9.10.3. I run choco.exe for test my chocolatey package on appveyor build server:

    $ErrorActionPreference = 'Stop';
    function Update-AppveyorTest {
        param (
            [string] $Name
            , [string] $Outcome
            , [long] $Duration
            , [string] $ErrorMessage
            , [string] $StdOut
            , [string] $StdErr
        ) 
        Write-Host "Test name: $Name; state: $Outcome; duration: $Duration; ErrorMessage: $ErrorMessage; StdOut: `n$StdOut; `n`nStdErr: `n$StdErr;";
    }

    function Execute-TestScript {
        [CmdletBinding()]
        param()
        & choco install font.gost2.304-81.install --force --confirm -pre --source "release/font.gost2.304-81.install/0.7.4";
    }
    $sw = [Diagnostics.Stopwatch]::new();
    try {
        Update-AppveyorTest `
            -Name testName `
            -Outcome 'Running' `
        ;
        $sw.Start();
        Execute-TestScript `
            -ErrorAction 'Stop' `
            -OutVariable stdOutStr `
            -ErrorVariable stdErrStr `
        ;
        $sw.Stop();
        Update-AppveyorTest `
            -Name testName `
            -Outcome 'Passed' `
            -Duration ( $sw.Elapsed.Milliseconds ) `
            -StdOut $stdOutStr `
        ;
    } catch {
        $sw.Stop();
        Update-AppveyorTest `
            -Name testName `
            -Outcome 'Failed' `
            -Duration ( $sw.Elapsed.Milliseconds ) `
            -StdOut $stdOutStr `
            -StdErr $stdErrStr `
        ;
        throw;
    };

And I can not redirect stdErr and stdErr choco streams! Why?

What is Expected?

choco.exe must write TRADITIONALY to stdout and errors - to stderr. With powershell I can't detect, successfully completed the test or not!

[ferventcoder]

@sergey-s-betke You are calling an external process, not a PowerShell script. You can't simply use common parameters OutVariable and ErrorVariable from an external process, only from the function you are calling or from calls to other PowerShell scripts with output.

I would suggest a search for suggestions on how you can do this - https://www.google.com/webhp?sourceid=chrome-instant&ion=1&espv=2&ie=UTF-8#q=outvariable+errorvariable+powershell+external+command

[sergey-s-betke]

@ferventcoder , I use advanced function syntax (Execute-TestScript) for wrapping external native .exe process for supporting -OutVariable and -ErrorVariable! This is one from many solutions for redirect streams for native .exe in powershell.

[sergey-s-betke]

@ferventcoder, for example, change line

& choco install font.gost2.304-81.install --force --confirm -pre --source "release/font.gost2.304-81.install/0.7.4";

to

& echo test test2 test3;

and $stdOutStr: 'test test2 test3', $stdErrStr: ''.

If I change line to

& echoErrorCmdLine test test2 test3;

and $stdOutStr: '', $stdErrStr: 'Unknown command echoErrorCmdLine'.

But for choco redirecting does not work!

[ferventcoder]

@sergey-s-betke choco just has regular stdout and stderr, so it's not on Chocolatey's end that this issue happens.

By the way run get-alias echo, it's not echo.exe like you think it is.

[sergey-s-betke]

five minutes, please...

[ferventcoder]

The second is a PowerShell error because you are not calling any process, so you are getting regular PowerShell error output.

[ferventcoder]

Try this

& where.exe choco

See if you get any output.

[sergey-s-betke]

'Stream' variables is empty... Thank You, I must search another solution for streams redirecting.

[ferventcoder]

Here's a pretty advanced scenario for redirecting output -

choco/src/chocolatey.resources/helpers/functions/Get-ChocolateyUnzip.ps1

Lines 131 to 175 in ab78454

	$writeOutput = {
	if ($EventArgs.Data -ne $null) {
	$line = $EventArgs.Data
	Write-Verbose "$line"
	if ($line.StartsWith("- ")) {
	$global:zipFileList.AppendLine($global:zipDestinationFolder + "\" + $line.Substring(2))
	}
	}
	}
	$writeError = {
	if ($EventArgs.Data -ne $null) {
	Write-Error "$($EventArgs.Data)"
	}
	}
	$process = New-Object System.Diagnostics.Process
	$process.EnableRaisingEvents = $true
	Register-ObjectEvent -InputObject $process -SourceIdentifier "LogOutput_ChocolateyZipProc" -EventName OutputDataReceived -Action $writeOutput | Out-Null
	Register-ObjectEvent -InputObject $process -SourceIdentifier "LogErrors_ChocolateyZipProc" -EventName ErrorDataReceived -Action $writeError | Out-Null
	$process.StartInfo = new-object System.Diagnostics.ProcessStartInfo($7zip, $params)
	$process.StartInfo.RedirectStandardOutput = $true
	$process.StartInfo.RedirectStandardError = $true
	$process.StartInfo.UseShellExecute = $false
	$process.StartInfo.WorkingDirectory = Get-Location
	$process.StartInfo.WindowStyle = [System.Diagnostics.ProcessWindowStyle]::Hidden
	$process.Start() | Out-Null
	if ($process.StartInfo.RedirectStandardOutput) { $process.BeginOutputReadLine() }
	if ($process.StartInfo.RedirectStandardError) { $process.BeginErrorReadLine() }
	$process.WaitForExit()
	# For some reason this forces the jobs to finish and waits for
	# them to do so. Without this it never finishes.
	Unregister-Event -SourceIdentifier "LogOutput_ChocolateyZipProc"
	Unregister-Event -SourceIdentifier "LogErrors_ChocolateyZipProc"
	# sometimes the process hasn't fully exited yet.
	Start-Sleep 1
	$exitCode = $process.ExitCode
	Set-PowerShellExitCode $exitCode
	$process.Dispose()
	Write-Debug "Command ['$7zip' $params] exited with `'$exitCode`'."

[sergey-s-betke]

Thank You! Ten minutes...

[sergey-s-betke]

@ferventcoder, script:

    function Update-AppveyorTest {
        param (
            [string] $Name
            , [string] $Outcome
            , [long] $Duration
            , [string] $ErrorMessage
            , [string] $StdOut
            , [string] $StdErr
        ) 
        Write-Host "Test name: $Name; state: $Outcome; duration: $Duration; ErrorMessage: $ErrorMessage; StdOut: `n$StdOut; `n`nStdErr: `n$StdErr;";
    }

    Update-AppveyorTest `
        -Name testName `
        -Outcome 'Running' `
    ;
    $process = [System.Diagnostics.Process]::new();
    try {
        $process.StartInfo = [System.Diagnostics.ProcessStartInfo]::new($env:ComSpec, '/C choco install font.gost2.304-81.install --force --confirm -pre --source "release/font.gost2.304-81.install/0.7.4"');
        $process.StartInfo.RedirectStandardOutput = $true;
        $process.StartInfo.RedirectStandardError = $true;
        $process.StartInfo.UseShellExecute = $false;
        $process.StartInfo.WorkingDirectory = Get-Location;
        $null = $process.Start();
        $process.WaitForExit();
        $stdOut = $process.StandardOutput.ReadToEnd();
        $stdErr = $process.StandardError.ReadToEnd();
        $duration = $process.ExitTime.Subtract( $process.StartTime );
        if ( $process.ExitCode -eq 0 ) {
            Update-AppveyorTest `
                -Name testName `
                -Outcome 'Passed' `
                -Duration ( $duration.Milliseconds ) `
                -StdOut $stdOut `
                -StdErr $stdErr `
            ;
            Write-Output $stdOut;
        } else {
            Update-AppveyorTest `
                -Name testName `
                -Outcome 'Failed' `
                -Duration ( $duration.Milliseconds ) `
                -StdOut $stdOut `
                -StdErr $stdErr `
            ;
            Write-Output $stdOut;
            Write-Error $stdErr;
        };
        exit( $process.ExitCode );
    } finally {
        $process.Dispose();
    };

It worked! But $strErr is empty... $strOut is ok... Why $process.StandardError is empty (with error on package installation)?

[ferventcoder]

Change

$process.StartInfo = [System.Diagnostics.ProcessStartInfo]::new($env:ComSpec, '/C choco install font.gost2.304-81.install --force --confirm -pre --source "release/font.gost2.304-81.install/0.7.4"');

to

$process.StartInfo = [System.Diagnostics.ProcessStartInfo]::new("$env:ChocolateyInstall\bin\choco.exe", 'install font.gost2.304-81.install --force --confirm -pre --source "release/font.gost2.304-81.install/0.7.4"');

I'm not sure I follow the purpose of this testing. While it is fine to capture both to determine if there were errors, you can simply look at exit code is not in a set defined in #512 (0 is not the only successful exit code) to determine if it failed.

In the way you are doing it feels a little much. You can find the duration time using Measure-Command and see the output simply by not redirecting it. Then you can fail it by the exit code not meeting one of the known items from #512.

[ferventcoder]

The reason I bring this up is that your output will be separated from your stderr, which may make it harder to pinpoint when that happened.