Logging & Redirection With PowerShell

My relationship with PowerShell got off to a pretty rocky start. After going through all the noddy examples and running a few one-liners that pulled data from remote machines via WMI I felt I was ready to tackle some Real World Problems. Given its promotion as a replacement for CMD.EXE it seemed wholly appropriate that I pick some of our batch files and convert them to PowerShell scripts to see whether you can convert them relatively easily. Sadly it seems that much like the Intel debacle with the 80286, the designers of PowerShell only expected you to go one way…

Batch File Logging

It’s a common pattern in batch files (i.e. .bat & .cmd files) to write progress and error messages out as you’re going along. So you often see this kind of pattern:-

@echo off
. . .
echo Starting something lengthy...
myprocess.exe
if errorlevel 1 (
  echo ERROR: Bad stuff happened!
  exit /b 1
)

In PowerShell ECHO is just an alias for the cmdlet write-output. Hence in PowerShell you could write something pretty similar:-

echo Starting something lengthy...
myprocess.exe
if ($lastexitcode -ne 0)
{
  echo ERROR: Bad stuff happened!
  exit 1
}

OK, so this isn’t idiomatic PowerShell as you can simplify the error handling. But that’s not what we’re interested in - it’s the logging. If you run this what you’ll find is that the each word is written on a separate line:-

C:\> PowerShell -File test.ps1
Starting
something
lengthy...

Oops! That alias doesn’t exactly work because PowerShell treats each word as a separate argument instead of a single line of text, so we need to surround the entire message in quotes:-

echo ‘Starting something lengthy...’
myprocess.exe
if ($lastexitcode -ne 0)
{
  echo ‘ERROR: Bad stuff happened!’
  exit 1
}

Now let’s try moving that into a function. If you’ve never used functions in batch files before you basically just invoke CALL with a label and use GOTO :EOF to return. This earlier blog post shows you the template I use for batch files which has functions to handle the usage message. Here’s our batch file again rewritten to use a function instead:-

@echo off
. . .
call :do_stuff %*
. . .
exit /b 0

:do_stuff
echo Starting something lengthy...
myprocess.exe
if errorlevel 1 (
  echo ERROR: Bad stuff happened!
  exit /b 1
)
goto :eof

The ECHO still works exactly as before. But when we do that in PowerShell things start to go a bit awry because the output from write-output does not go to the console, but it becomes the output from the function instead:-

function do-stuff()
{
  echo ‘Starting something lengthy...’ 
  myprocess.exe
  if ($lastexitcode -ne 0)
  {
    echo ‘ERROR: Bad stuff happened!’
    exit 1
  }
}

do-stuff

So long as you don’t want to capture the function output (e.g. using $result = do-stuff) it will go to the console. But the moment you want to start writing real functions and you also want diagnostic logging too you have to change tact. To be fair you can’t write “proper” functions in batch files anyway and so the conversion so far has been pretty good; although I personally think the choice of an alias for ECHO was possibly a bad one.

The designers of PowerShell probably thought that the moment you want to do non-batch-file stuff you should start using the correct PowerShell cmdlets - write-host, write-error, etc. But that doesn’t quite work as seamlessly as you’d hope either.

What Platform Is This?

Pop quiz. What is/are the line termination character(s) in Windows? Everyone knows this, it’s CR/LF, or a carriage return followed by a line-feed. But not in PowerShell it seems. The obvious replacement for write-output is to log with write-host, after all, that writes directly to the console. So, try this:-

C:\> PowerShell "write-host hello; write-host world" > stdout.log
C:\> more stdout.log
C:\> type stdout.log
C:\> notepad stdout.log

I’m sure you can’t be bothered to run this so let me show you the output from MORE and TYPE:-

C:\> more stdout.log
hello
world

Of course you get two separate lines. Why, what else did you expect? In notepad though you’ll see this instead:-

helloworld

Put your hand up if your default log file viewer is notepad? On a developer’s workstation you probably have a plethora of text editors, “tailers” and Unix-like tools. But on production Windows hardware it’s almost certainly just notepad. And you’d be surprised how many sysadmins I’ve seen that think nothing of loading a multi-megabyte log file by double-clicking it and firing it up in notepad[1].

If you look at the redirected text file it doesn’t have the expected dual terminators (0x0D, 0x0A), just the single Unix line ending (0x0A). OK, so many text processing tools are aware of the differences between line-endings on Windows and Unix, but as Notepad shows some also still aren’t. This means that using write-host directly isn’t quite enough, what we need to do is manually output the correct line-ending. The following function called “write-line” does exactly that:-

function write-line ($line)
{
  write-host -nonewline "$line`r`n"
}

This function uses write-host and so it also works perfectly well from any functions you write without interfering with any return value. The only quibble might be with the name as Write-LogMessage might perhaps be more in keeping with the PowerShell style.

Truncated Log Output

The final problem I ran into has now been documented fairly well in other blog posts and on Stack Overflow and concerns the truncation of log message output when redirecting PowerShell output with CMD.EXE. When developing batch files, such as for a build process, you generally see the output in the console window which is what you want. But the moment you automate it, such as with the Windows Task Scheduler you need to capture all that output in case something goes wrong. In essence what you run is something like this:-

C:\Dev> BuildAll.cmd > C:\Logs\BuildAll.out.log 2> C:\Logs\BuildAll.err.log

If your BuildAll.cmd script generates a long log message like this:-

@echo off
echo A very long line of text that will not wrap because CMD.EXE pays no attention to the console window width when being redirected

The captured log file will look as expected with CMD.EXE - all the message is on a single line. Now, if we convert that batch file to PowerShell and capture the output again things don’t look so good:-

echo ‘A very long line of text that will likely wrap because PowerShell will use the console window width even when being redirected’

If you open the log file in notepad you’ll see the message has been truncated to the width of the (almost invisible) console window that was used to invoke the script. Here is how the redirected text is wrapped on a small console window:-

A very long line of text that will
likely wrap because PowerShell will
use the console window width even
when being redirected

This will happen with the write-output cmdlet, but doesn’t with write-host. So, if we instead use our new “write-line” function we’re all peachy again:-

function write-line ($line)
{
  write-host -nonewline "$line`r`n"
}

write-line ‘A very long line of text that won’t wrap because PowerShell will ignore the console window width when using write-host’

If you’ve looked into the other solutions to this particular problem you’ll see that they suggest you play with the UI.RawUI.BufferSize setting. When I first tried that it failed because the console window I was using had a height of 100 lines and trying to set it to only 50 failed. Personally I dislike both workarounds but mine does feel marginally “less dirty” to me.

Redirection is the Caller’s Responsibility

One answer to the complaint about the redirection issue is the use of the start-transcript cmdlet. I don’t agree with this answer because I believe it’s the caller of the script that should determine when and where to redirect any output. The power of the Unix tools such as TEE comes from the very fact that they are simple and that you use composition to achieve your goal. PowerShell is a command line tool that tries, and largely succeeds, in exploiting this concept within its language, but sometimes fails to be composed itself in the same way.

 

[1] Naturally I try to educate them into using slightly more efficient tools, after all it’s probably more painful for me to watch than it is for them to do.