August 11, 2009

Best Practices for the Flex Logging Framework

Introduction

The Flex Logging Framework is easy to learn and flexible to use. It supports many different scenarios, from helping developers to debug their code, to sending the details of production application errors over the wire to a remote server for monitoring. To learn the basics of the Logging Framework refer to the latest Flex Developer Guide and the Flex Logging Framework chapter of Professional Flex 3. This document describes some best practices for applying the Logging Framework on enterprise projects.

The APIs provided by the Logging Framework are simple, but they need to be used properly to get the best out of them. If care is not taken, the benefits that logging can provide for debugging and monitoring an application in production can be lost. Performance problems can even be created. This article provides a set of best practices to keep the developers in your team on the right track.

Best Practices

The following best practices are covered:

1. Get Loggers by Class
2. Declare Loggers as Static Constants
3. Format Log Statements Consistently
4. Parameterize Log Statements with Tokens
5. Use Log Levels to Indicate Severity
6. Use Log Filters for Focus
7. Include Categories to Show Class Names
8. Use Guard Conditions Appropriately
9. Configure Logging at Runtime

Get Loggers By Class

Use a simple utility method to retrieve the logger for a particular class, instead of passing in the qualified class name as a string.

Good:

private static const LOG:ILogger = LogUtil.getLogger(MyClass);

Bad:

private static const LOG:ILogger = Log.getLogger(“my.package.MyClass”);

With the utility method approach, the class name can be refactored without needing to edit the string. Here is an implementation for the LogUtil.getLogger() method:

public static function getLogger(c:Class):ILogger 
{
    var className:String =  
        getQualifiedClassName(c).replace("::", ".")
    return Log.getLogger(className);
}

If performance profiling shows this method call to be a performance bottleneck, you may decide to revert to passing in the class name manually, since this will run a little faster. However, in most cases the convenience and refactor-ability of the above approach is the best practice.

Declare Loggers as Static Constants

In most cases, log statements apply to a particular class, so a logger should be declared as a static constant and not an instance variable.

Good:

private static const LOG:ILogger = LogUtil.getLogger(MyClass);

Bad:

private var log:ILogger = LogUtil.getLogger(MyClass);

Format Log Statements Consistently

Log statements should be formatted consistently and not haphazardly. This ensures that logging code looks professional and improves readability of log files (for humans or machines).

Good:

LOG.error(
    "Something bad has happened: event={0}, message={1}", 
    event.type, 
    message);

Bad:

LOG.error("-----------  SOMETHING BAD HAS HAPPENED!  -----------------");

Parameterize Log Statements

Parameterize log statements using the rest parameter and tokens, instead of appending strings manually. This produces cleaner code and prevents the composite string from being assembled in the event that no log target is registered.

Good:

LOG.debug(
    "Something interesting is happening: event={0}, message={1}", 
    event.type, 
    message);

Bad:

LOG.debug(
    "Something interesting is happening: event=" + 
    event.type + 
    ", message=" + 
    message);

Use Log Levels to Indicate Severity

Use the debug/info/warn/error log levels to indicate the severity of the message, instead of emphasizing important messages with special characters.

Good:

LOG.error("The service has failed and no data is available.");

Bad:

LOG.debug("!!! ERROR !!! The service has failed !!! ERROR !!!");

Use Log Filters for Focus

Set the log filters on your logging targets in order to focus on the logs produced by a certain part of the system. Do not instead try to make certain log statements stand-out with special characters. Remember to keep the format of log messages consistent.

Good:

target.filters = [ "my.important.package.MyClass" ];
target.level = LogEventLevel.INFO;
...
LOG.info("My important message");

Bad:

LOG.debug("----------- My really important message! -----------");
LOG.debug("<<<<<<<    another super important log!    >>>>>>>>");
LOG.debug("************* CAN YOU SEE ME????? ***************");

The trouble with the “special character” approach is that what is important for one developer one day is different to what is important for another developer on another day. If every developer uses their own notation for making their logs stand-out, the resulting log file becomes harder to read than when no emphasis has been placed in the text. Log levels and filters provide a more controllable and consistent mechanism for the same purpose.

Include Categories to Show Class Names

If you want to see the name of the class issuing a log statement, include categories for your log targets. Do not instead hard-code the name of the class into log statements.

Good:

target.includeCategory = true;
...
LOG.debug("Executing command");

Bad:

LOG.debug("<<<   Executing SynchronizationCommand   >>>");

The bad practice above is not refactor-safe. If the class is renamed, the message becomes confusing and if categories are included in the output, part of the message becomes redundant.

Use Guard Conditions Appropriately

Use guard conditions to prevent unnecessary processing where a log statement is expensive or nested within a loop or iteration. However, do not use guard conditions around every single log statement since this clutters up code. Decide whether or not the log statement may be expensive or use the profiler to verify this.

Good:

if (Log.isDebug())
{
    LOG.debug("Result received: {0}", ObjectUtil.toString(model));
}

for (var i:int = 0; i<10000; i++)
{
    if (Log.isDebug())
    {
        LOG.debug("Blah blah blah: i={0}", i);
    }
}

Bad:

LOG.debug("Result received: {0}", ObjectUtil.toString(model));

for (var i:int = 0; i<10000; i++)
{
   LOG.debug("Blah blah blah: i={0}", i);
   ...
}

In the bad practice above, the model will be converted into a string even if there is no registered target for the debug-level. Similarly, 10,000 log statements will be issues inside the loop regardless of whether or not there is a target registered.

Configure Logging at Runtime

Configure logging at runtime is a best practice, since it allows developers to change their log filters without rebuilding and also allows logging to be reconfigured in production without redeploying. Different log settings can even be applied to different users.

The process for configuring logging at runtime is beyond the scope of this article, however, the Parsley 2 Application Framework provides a feature for doing precisely that by loading an external XML file that specifies the targets, levels and filters. There are also examples available showing how to do the same thing using Prana/Spring ActionScript.

Posted by tsugden at 9:15 AM | Comments (2)