Weird Powershell Standard Error Behavior

Ok I’m baffled. I am working on the previously mentioned powershell perforce backup script. I intentionally corrupted one of my database files to make sure I’m correctly catching the error. This ran me into a brick wall with trying to trap some standard error output from Perforce. At least I think it’s standard error. At this point I could be convinced some new output stream has mysteriously been created that redirects output to some black hole.

Setting the script aside, let’s take a look at the basics. Here’s what happens in a standard dos command window:

F:\p4backup>p4d -r F:\P4ROOT -xv > test.log 2>&1
 
F:\p4backup>type test.log
Validating db.counters
Validating db.logger
Validating db.user
Validating db.group
Validating db.depot
Validating db.domain
Validating db.view
Validating db.review
Perforce server error:
        Database open error on db.have!
        BTree is corrupt!
 
F:\p4backup>

Now let’s try it in powershell:

PS F:\p4backup> p4d -r F:\P4ROOT -xv > test.log 2>&1
PS F:\p4backup> type test.log
Validating db.counters
Validating db.logger
Validating db.user
Validating db.group
Validating db.depot
Validating db.domain
Validating db.view
Validating db.review
PS F:\p4backup>

No error! It mysteriously disappeared. Ok this lead me to believe something funky was up with standard error redirection, so I wrote a little standard error test program:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
 
namespace StandardErrorTester
{
    class Program
    {
        static void Main(string[] args)
        {
            Console.WriteLine("This is being written to standard output.");
            Console.Error.WriteLine("This is being written to standard error.");
        }
    }
}

Let’s run the test program in a dos command window:

F:\p4backup>StandardErrorTester.exe > error.log 2>&1
 
F:\p4backup>type error.log
This is being written to standard output.
This is being written to standard error.
 
F:\p4backup>

Works as expected. Now let’s try it in powershell:

PS F:\p4backup> .\StandardErrorTester.exe > error.log 2>&1
PS F:\p4backup> type error.log
This is being written to standard output.
StandardErrorTester.exe : This is being written to standard error.
At line:1 char:26
+ .\StandardErrorTester.exe  <<<< > error.log 2>&1
PS F:\p4backup>

The standard error does get wrapped with some strange powershell stuff, but all the output is present. I’m wondering if in the perforce case, the errors are getting interpreted and hidden somehow. Very strange.

Here is simple work around. It’s a function that takes what you want to execute, executes it via a batch script which makes the context the dos command shell. You can still check $LASTEXITCODE and filter the function through pipes or redirection. It’s ugly because it has to create a stub batch file, but it gets around the problem I’m having.

function RunCombineStdErrStdOut
{
    param([string]$commandLineToRun)
    # Get the path where the current script is so we can create
    # our batch file next to it
    $curScript = $script:myInvocation.MyCommand.Path
    $curPath = (Split-Path $curScript)
    # We're going to create a batch file right next to our ps1 script, wherever it lives.
    $runCombBatchFile = $curPath + "\RunCombineStdErrStdOut.cmd"
    if (test-Path -path $runCombBatchFile)
    {
        # Remove the batch file if it exists before we start 
        remove-Item $runCombBatchFile
    }
    # Create our tiny batch script to combine standard error and standard out
    write-Output '@echo off' | out-file $runCombBatchFile -enc ascii -append
    write-Output 'REM This script is auto-created by a PowerShell script' | out-file $runCombBatchFile -enc ascii -append
    write-Output 'REM Modifications will be lost. Do not edit directly' | out-file $runCombBatchFile -enc ascii -append
    write-Output ('REM Script Created by: ' + $curScript.ToString()) | out-file $runCombBatchFile -enc ascii -append
    # %* is a little trick that refers to all the paramters, not just a single one
    # Remove comment for debugging
    #write-Output 'echo Running %*' | out-file $runCombBatchFile -enc ascii -append
    write-Output '%* 2>&1' | out-file $runCombBatchFile -enc ascii -append
    # This will execute the batch file with the command passed to the function
    Invoke-Expression ($runCombBatchFile + " " + $commandLineToRun)
    # You can still check $LASTEXITCODE once this executes
    # it will reflect whatever command we executed
}
 
 
#  Just a simple example to get you going
RunCombineStdErrStdOut "ipconfig /all"
This entry was posted in General and tagged . Bookmark the permalink.

Leave a Reply

Your email address will not be published. Required fields are marked *