InnerException: We have to go deeper.

I helped a co-worker with an interesting issue today.  He was writing a PowerShell script that downloads a file.  He wanted to catch any errors with the download, so he had some code like this:

$client = New-Object System.Net.WebClient
try {
  $client.DownloadFile('http://www/files/file.txt', file.txt)
catch [System.Net.WebException] {
  # $_ is set to the ErrorRecord of the exception
  Out-Log $_.Exception.Message
}

This usually works, returning the text of the error, but this time he was getting back:

An exception occurred during a WebClient request.

That's not a very informative error.  Removing the try/catch blocks, he got this on the screen:


System.Net.WebException: An exception occurred during a WebClient request. ---> System.UnauthorizedAccessException: Access to the path 'C:\Users\tojo2000\hosts.txt' is denied.
   at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
   at System.IO.FileStream.Init(String path, FileMode mode, FileAccess access, Int32 rights, Boolean 
...


So obviously the information is in there somewhere.  It turns out that WebException usually returns the error code of the request, but if it runs into an error that is not related to the actual download, it will add the second exception to a property of the WebException object called InnerException.  

So the updated code looks something like this:


$client = New-Object System.Net.WebClient
try {
  $client.DownloadFile('http://www/files/file.txt', file.txt)
catch [System.Net.WebException] {
  # $_ is set to the ErrorRecord of the exception
  if ($_.Exception.InnerException) {
    Out-Log $_.Exception.InnerException.Message
  } else {
    Out-Log $_.Exception.Message
  }
}


Now we get the correct output:


Access to the path 'C:\Users\tojo2000\hosts.txt' is denied.

When Is a String Not a String?

I came across a really difficult-to-troubleshoot bug today, a real brain-teaser.

A co-worker asked me to help him figure out why his PowerShell script was running a certain piece of code even though it shouldn't.  He had a piece of code to detect a bad Windows Installer exit code like this:

$result = InstallSomeSoftware
if ($result -eq "1603") {
  #do something...

The "do something part was being executed no matter what value he returned from the InstallSomeSoftware function.  To troubleshoot, he added some Write-Host statements to display the return value on the screen before returning it inside the function.  Sure enough, the expected value was printed on the screen, and it was not 1603.

We both scratched our heads for a while, stepped through the function, and still weren't getting anywhere, when I noticed a few random lines of output.  We realized that there were lines in his function that were returning values and not being captured by any variable or thrown away, so they were also being returned along with the expected value.

So that leaves one last piece of the puzzle.  Why would everything always evaluate to True when compared to the string "1603"?  After a little more digging we had the answer.  The first value being returned had the value True.  -eq, when attempting to determine equality, saw that the two object types weren't the same, so it did what it was supposed to do:  it cast the string "1603" as a System.Boolean and then checked to see if True was equal to  True (which is what the string "1603" evaluates to as a Boolean).

Many hairs were lost in this battle, but at least in the end we had our sanity.

The 2011 Scripting Games Start Today!

Just a reminder to get scripting.  I'm going to try to make the time to participate in each event this year, and then I'll be posting my solutions here after the submissions are closed.

If you're interested in the Scripting Games at all, I suggest you bookmark this URL:  All 2011 Scripting Games links on one page.

One Approach to Logging in PowerShell

I was writing a script recently, and I realized that I was missing the ability to use the standard logging module from Python.  I decided to make a stripped-down logging function that would make logging easy, and that could be re-used.  I'd be interested to hear what approaches others have taken to solving this problem.  Here's what I came up with:



# Set severity constants
$MSG_INFORMATION = 0
$MSG_WARNING = 1
$MSG_ERROR = 2
$MSG_SEVERITY = @('Information', 'Warning', 'Error')


# Set configurable settings for logging
$LOG_LEVEL = $MSG_INFORMATION
$LOG_FILE = 'my_logfile.log'
$SMTP_TO = 'devnull@tojo2000.com'
$SMTP_SERVER = 'smtp.tojo2000.com'
$SMTP_SUBJECT = 'Script error!'


function Write-Log {
  <#
  .SYNOPSIS
     Writes a message to the Log.
  .DESCRIPTION
    Logs a message to the logfile if the severity is higher than $LOG_LEVEL.
  .PARAMETER severity
     The severity of the message.  Can be Information, Warning, or Error.
     Use the $MSG_XXXX constants.
     Note that Error will halt the script and send an email.
  .PARAMETER message
     A string to be printed to the log.
  .EXAMPLE
     Log $MSG_ERROR "Something has gone terribly wrong!"
  #>
  param([Parameter(Mandatory=$true)][int]$severity,
        [Parameter(Mandatory=$true)][string]$message)


  if ($severity -ge $LOG_LEVEL) {
    $timestamp = Get-Date -Format 'yyyy-MM-dd hh:mm:ss'
    $output = "$timestamp`t$($MSG_SEVERITY[$severity])`t$message"
    Write-Output $output >> $LOG_FILE


    if ($severity -ge $MSG_ERROR) {
      Send-MailMessage -To $SMTP_TO `
                       -SmtpServer $SMTP_SERVER `
                       -Subject $SMTP_SUBJECT`
                       -Body $output `
                       -From $SMTP_FROM
      exit 1
    }
  }
}

Nothing To DO With PowerShell

Just a quick update to plug one of my other projects: py-ad-ldap.  Have you ever wanted to run scripts against Active Directory but not wanted to run them on Windows?  You haven't?  Well, if you had, then this would have been the Python module for you.  I haven't packaged it up for download yet (hopefully tomorrow), but it's pure Python, so there are no fancy requirements for installing it, so mosey on down to the repository and take a look at the source files if you're interested.

Getting Performance Counters in PowerShell

I had a friend ask me recently if there was an easy way to monitor arbitrary performance counters in a script, and I didn't really have time to think about it at the time, but this weekend I decided to give it a whirl, and I came up with this function, that I'll definitely be putting in my profile at work.

The way it works is pretty straightforward, but you need to know some background about Performance Counters if you haven't used them before.  There are basically four pieces of information needed to retrieve a counter:

• Category
• Counter
• Instance
• Computer

If these don't ring a bell right away, fire up Perfmon, right-click and select Add Counters, and you'll see something like this:

In the top-left box you can see the Categories, and if you expand them you'll see the Counter names, and bottom left are the Instances.

Classic example: you want to find out the Current Disk Queue Length on your C: drive.

• Category = 'LogicalDisk'
• Counter = 'Current Disk Queue Length'
• Instance = 'C:'
• Computer = '.' (default, it means "this computer")

Using Get-PerformanceCounter, you'd do it like this:

Get-PerformanceCounter LogicalDisk 'C:' 'Current Disk Queue Length'

Or lets say you want to get all of the counters for the C: drive:

Get-PerformanceCounter LogicalDisk 'C:'

Anyway, here's the function, and you can also find it here: http://poshcode.org/2475