Assert and Exception Logging made easy in PowerShell

In this post I would like to present you a way of how to easily perform assertions like error checking and result validation with PowerShell based on an idea of the Microsoft Code Contracts library.

We at d-fens spend quite some time writing PowerShell scripts that automate and integrate various backend systems where unforeseen events not only happen but are on our daily agenda. For us it is therefore very important to be able to quickly track down the errors and get good insight what actually happened. Previously we tackled this with classic try/catch blocks that would wrap everything inside our Cmdlets and dump a stack trace when something went wrong. In addition we added plenty of if($someErrorOccurred) { } to guard the result of our invoked actions.

However, this tended to produce some bloated and hard to read code, so therefore we came up of adapting Contract.Assert() and Contract.Requires() to the PowerShell ecosystem.

The basic idea behind it was to:

  • differentiate between preconditions and assertions
  • provide a standard way to log exceptions (based on precondition and assertion failures)

For this we created a Cmdlet Log-Exceptionthat would log an ErrorRecord via our biz.dfch.PS.System.Logging module. In this Cmdlet we take the information of the caller, stackframe, Exception and any InnerExceptions and log them to our standard log. Then we set up a trap handler for each script block that requires it (BEGIN, PROCESS and END). For the actual error checking and validation we created a second Cmdlet with two aliases Contract-Assert and Contract-Requires that would raise an exception to be picked up by the trap handler.

We use Contract-Requires to indicate an input error condition (i.e. a pre-condition to run this script has not been met) and Contract-Assert to detect runtime errors (such as an invoked script did not return a required result).

In real life this looks like this:

function Test-Funcenstein
{
[CmdletBinding()]
PARAM
(
[string] $InputObject
)

Process
{
trap { Log-Exception $_; break; }

# assert with standard error message
Contract-Requires ($ENV:JAVA_HOME -match 'jre8$')

# output on failure will look like this:
# WARNING: : Precondition failed: ($ENV:JAVA_HOME -match 'jre8$')

# assert with detailed error message
Contract-Requires ($ENV:JAVA_HOME -match 'jre8$') 'No Java 8 runtime found'

# output on failure will look like this:
# WARNING: : Precondition failed: ($ENV:JAVA_HOME -match 'jre8$') 'No Java 8 runtime found'

# do some processing
$result = Get-ChildItem -Filter *.class;

# assert with standard error message
Contract-Assert ($result.Count -gt 0)

# output on failure will look like this:
# WARNING: : Assertion failed: ($result.Count -ge 1)

# assert with detailed error message
Contract-Assert ($result.Count -gt 0) 'No class file to process'

# output on failure will look like this:
# WARNING: : Assertion failed: ($result.Count -ge 1) 'No class file to process'
}
}

For specific exception handling in the code we can use regular try/catch[SomeNiftyException] constructs. The trap handler acts like our global exception handler.

The log file (depending on your configuration) will then have an entry similar to this (lines wrapped for readability). There you can also see the remark [Contract-Requires] indicating which error condition was found:

2015-12-26 05:42:08.015+01:00|ERROR|47ab7539-d5b7-4b19-8b2b-780c75f98a3a|
Default|Exception and Error Handling|Test-Funcenstein|
[Contract-Requires] 'Precondition failed: ($ENV:JAVA_HOME -match 'jre8$')' [System.Management.Automation.RuntimeException]

ErrorRecord : Precondition failed: ($ENV:JAVA_HOME -match 'jre8$')
StackTrace :
WasThrownFromThrowStatement : True
Message : Precondition failed: ($ENV:JAVA_HOME -match 'jre8$')
Data : {}
InnerException :
TargetSite :
HelpLink :
Source :
HResult : -2146233087

Location Command Arguments
-------- ------- ---------
Out-MessageException.ps1: line 76 Out-MessageException {ErrorRecord=Precondition failed: ($ENV:JAVA_HOME -match 'jre8$')}
Test-Funcenstein {InputObject=sdafasdf}
Test-Funcenstein {InputObject=sdafasdf}
{}

Hopefully this will help you in your scripts, too! You can download the scripts from biz.dfch.PS.System.Logging or via NuGet or PowerShell Gallery.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: