PowerShell Script Logging and Tracing

From Redmond, WA.  I’m at the Platform Adoption Center (PAC) (Building 20) for Apr 18-19 at the PowerShell & MMC ISV Workshop.

In some scripts, especially longer ones, you might find it handy to use logging and tracing that you can turn up or down, depending on the context and depending on yours needs at the time you are running the script.

Using a logging framework would let you replace your ‘write-host’ statements with logging statements that will have the following characteristics:

  • You can turn them on or off with a single line edit (at the beginning of your script)
  • You can re-direct them to various destinations – console, file, event log – again with a single line edit
  • You can adjust the detail of the log entries – again with a single line edit

The need is so common in application development that there are multiple solutions.  The three that stand out the most (probably) are the PowerShell cmdlets write-* (including write-debug, write-warning, write-error, etc), log4net, an open source solution available from Apache, and the Enterprise Library logging application block from Microsoft’s patterns and practices group.

During script development, it is going to be handy to have verbose output of these logging statements turned up so that you know what is going on in the code, not just by looking at the results but also by looking at a record of has been run.  During production script runs, you might need to have a log of everything your script does.  Then again in some situations, you only want to see the logging statements that are associated with errors or other exceptional conditions.

Adding logging might be overkill for exploratory scripting – a scripting technique that PowerShell supports so well with the ‘get-member’ and ‘get-history’ cmdlets.  But I can imagine that if you ‘productionalize’ those scripts developed in an exploratory scripting session, then replacing ‘write-host’ with a logging statement might be a valuable refactoring.

I’ll let you choose which of the above options is best for you as an administrative scripter, but I’m inclined to think that you might go with the flow – whatever the application developers are using will probably already work for you.  If there are no application developers to follow (or lead), then the PowerShell write-* cmdlets might serve you well enough.

Script Logging with Write-* Cmdlets

PowerShell has built-in cmdlets for logging that use the verb "write".  Running the command "get-command write*" will list those commands for you (and a couple of other ones).  Each one is controlled by a shell variable that ends with "Preference". For example, to turn the warning messages up, then set the variable $WarningPreference to "Continue". Other options are Stop, Inquire, and SilentlyContinue. To turn down logging, set each of the $*Preference session variables to "SilentlyContinue". To turn up logging, then set them all to "Continue".

Note – if you’re building cmdlets, then there are base class methods that work with the same $*Preference shell variables.  Your cmdlets will be better received if you use them.

Script Logging with Log4net

Log4net has the advantage of having a very small footprint and, appropriate for scripters, it doesn’t require a configuration file.  Once you downloaded and unzipped the log4net binaries in a known location (hereinafter referred to as $Log4NetHome) you can use it something like this:

 

$logpattern = ` "%date [%thread] %-5level [%x] - %message%newline" # load the log4net library [void][Reflection.Assembly]::LoadFile($Log4NetHome + "log4net.dll") # configure logging [log4net.LogManager]::ResetConfiguration() $Appender = new-object log4net.Appender.ConsoleAppender(` new-object log4net.Layout.PatternLayout($logpattern))[log4net.Config.BasicConfigurator]::Configure($Appender) # determines the log statements that show up $Appender.Threshold = [log4net.Core.Level]::Info$Log = [log4net.LogManager]::GetLogger($Host.GetType()) $Log.Info("Started the main script...") trap { $Log.Error("Failed...") return/continue/break } #... # run your script here, including other $Log.Info statements #... $Log.Info("Finished the main script.")

In this example, the value of $logpattern is what determines the output of each log statement – the items preceded by the % character are log4net macros that correspond to attributes of the log statement, including what you have specified, %message.  The call to ResetConfiguration() is necessary if you tend to re-run the scripts in the same PowerShell session, otherwise you will have to take care to declare the logger variables as having script scope instead of the global scope (the default).

To configure the logging, you really only have to identify the layout of the log entries and an appender to use.  As presented above, the ConsoleAppender is used so that the log entries appear in the console.  There are also FileAppenders available as part of the framework.  I’ve used the PatternLayout here so that the pattern string $logpattern can dictate what shows up for each log entry.  There are other Layouts available, including a SimpleLayout that just lists the category and message for each log entry.

The output of the log entry in this case is something like the following:

2007-04-18 08:30:49,650 [Pipeline Execution Thread] INFO
[null] - Started testing parsing.
2007-04-18 08:30:49,400 [Pipeline Execution Thread] ERROR
 RfcParseExceptionHandler [RFCWorker] - PRS-
012:Unrecognized dish: Irregular
2007-04-18 08:30:49,650 [Pipeline Execution Thread] INFO
[null] - Finished testing parsing.

Changing the log level from "Info" to "Error" would result in only that second log entry being logged – the other ones would be ignored and not show up in the output.

You can match the pattern layout string above to see what each macro generates in the log file.  What I have also found handy was using the NDC stack in log4net to identify where the script was running at the time of the log entry.  The contents of the NDC stack is presented in the pattern by %x, so you can see that in the three log entries that are in the sample output, the value is only expressed in the second one.  Just so happens that’s the one that was generated by the C# class library that the PowerShell script was testing.  To use the NDC stack in your script, just push a string onto it in an appropriate line preceding what you want to log, and then pop it off the stack afterwards:

 
[log4net.NDC]::Push("test-getrfcaction-account") // //... do your thing, including log statements // [log4net.NDC]::Pop()

In this sample, that would put the phrase ‘test-getrfcaction-account’ will appear instead of the ‘null’ text that appears there now.  If you push multiple values onto the stack, then as you might expect, the appended stack message will appear in those log statements, consisting of all values that have been pushed but not yet popped.  Hey, it’s a stack.  You can appreciate that if you have several script file or several functions running, you might want to identify where the log entry is sourced from.

For my purposes, the developers were already using log4net in their application so using log4net in my test scripts seemed like a reasonable decision.  I do find the single edits handy – I can exclude the informational log entries by changing the Appender.Threshold property to "Error".  I change the log level alot because I’m exploring a bit with the PowerShell test scripts, so until I know for certain how the code I’m testing behaves, I keep it verbose. Last thing I do before adding the test scripts to the regression suite is change the log level to "Error".

So the happy conclusion is –

  • add log statements throughout your script
  • show your work by changing the log level threshold to "Info"
  • hide your work by changing the log level threshold to "Error"
  • change what shows up in each log entry by editing a pattern string
  • provide a basic version of your custom script call stack using the built-in logging stack (called the NDC)

Hope this helps!

Advertisements

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