Captains Log

It’s not galmourous or exciting, but good logging is critical to the long term survival of any large application. Logging in Java has a bit of a sordid history, with a few bad decisions made in the early days that still cause some lingering hassles. More recent frameworks have patched over some of this mess but there’s still a few hoops we have to jump through to setup simple logging.

Since JavaFX 2 uses standard Java we have all the same logging options (and hassles) as with any normal Java application. In this post we’re going to look at integrating goold old Log4J into our First Contact application. We’re also going to make use of SLF4J, which is a generic logging API that sits ontop of Log4J. Using this generic API we can keep our code free from specific Log4J dependencies, which allows us to change between any of the supported logging frameworks simply by changing configuration files (SLF4J also has binding for a number of other logging platforms such as java.util.logging, and Apache Commons Logging).

We’ll add logging support to both our client and our server. We could therefore put all the setup in the common module, so we only need to configure it one place. This is a bit of a coincidental symmetry however – there is no technical reason that the client and server should share the same logging infrastructure, particularly at a configuration level (we often want different logging levels for client and server). As such, I tend to setup logging in the client and server completely independently of each other, giving me the option to change one, should I have need, without impacting the other. If this approach doesn’t sit well with you, feel free to merge all the following setup in the common module.

Step 1: Add the dependencies

Starting with our previous code base once again, the first thing we need to do is include the SLF4J and Log4J dependencies in both our client POM and server POM. The additional dependencies are:

<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.6.4</version>
</dependency>

<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-log4j12</artifactId>
    <version>1.6.4</version>
</dependency>

<dependency>
    <groupId>log4j</groupId>
    <artifactId>log4j</artifactId>
    <version>1.2.16</version>
</dependency>

As well as the base libraries for Log4J and SLF4J, we’ve also defined the SLF4J-to-Log4J binding. Adding this JAR is all the configuration we need to make SLF4J use Log4J as its implementation – SLF4J detects the available binding at startup and uses it automatically.

Step 2: Add log calls to our code

To log messages from within our code, we need to define Loggers. Typically you define one per class that you are logging from, and define the Logger as a static instance in that class. So for example if we want to log from within the ContactSearchPresenter class we do the following:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class ContactSearchPresenter implements Initializable
{
    private static final Logger log = LoggerFactory.getLogger(ContactSearchPresenter.class);

    ...
}

And in the ContactDetailPresenter we do the following:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class ContactDetailPresenter
{
    private static final Logger log = LoggerFactory.getLogger(ContactDetailPresenter.class);

    ...
}

Once we have these Loggers setup we can then use them along the lines of the following:

public void search(ActionEvent event)
{
    String searchPhrase = searchField.getText();
    final String[] keywords = searchPhrase != null ? searchPhrase.split("\\s+") : null;
    final Task<List<Contact>> searchTask = new Task<List<Contact>>()
    {
        protected List<Contact> call() throws Exception
        {
            log.info("Searching for contacts, keywords = {}", keywords);
            return contactService.searchContacts(keywords);
        }
    };

    searchTask.stateProperty().addListener(new ChangeListener<Worker.State>()
    {
        public void changed(ObservableValue<? extends Worker.State> source, Worker.State oldState, Worker.State newState)
        {
            if (newState.equals(Worker.State.SUCCEEDED))
            {
                List<Contact> matches = searchTask.getValue();
                log.info("Found {} matching contacts", matches.size());
                resultsList.getItems().setAll(matches);
            }
            else if (newState.equals(Worker.State.FAILED))
            {
                Throwable exception = searchTask.getException();
                log.error("Contact search failed", exception);
            }
        }
    });

    new Thread(searchTask).start();
}

SLF4J supports token replacement in the search phrases. So if you call something like:

log.info("value1 = {}, value2 = {}", value1, value2);

then each of the ‘{}’ elements will be replaced by the value passed in. For backwards compatability reasons they’ve not used varags so if you want to do more than two parameters you have to create an array, so something like:

log.info("value1 = {}, value2 = {}, value3 = {}", new Object[] {value1, value2, value3});

When you log an ‘error’, you can pass an exception as the parameter instead of the value replacements. In this case, the full stack trace of the exception will be logged along with the message you provide.

See the SLF4J documentation for more information on all of this.

Choosing how, when and where you log is an architectural decision that should be based on your particular needs (i.e. the complexity of your application, the usage of it, etc). The main levels available are ‘error’, ‘warn’, ‘info’, ‘debug’ and ‘trace’.

‘Error’ and ‘warn’ are pretty self explanatory. I tend to use ‘info’ to track the high-level user flow (e.g. “the user is now adding a new contact called John Smith”) so that this log can be used to trace back what the user was doing (or trying to do). I then use ‘debug’ for finer-grained, processing details (e.g. “Contact John Smith was created with ID 31″). Occasionally I will use ‘trace’ for very low level debugging, such as when iterating through a a loop with complex logic.

In the server, I tend to log at least one ‘info’ message in every service call. In the client, I tend to log an ‘info’ message at least once per Presenter method. I then generally add ‘debug’ logging in a more add-hoc fashion in the places where I think it will be useful. I generally don’t do a lot of logging inside the view (since you can usually see this stuff anyway), unless the view logic is doing something a little complex like dynamically loading a sub-view based on state, etc.

It’s considered good practice to also enclose your logging in an ‘if’ check to make sure the level of logging is enabled. So for a debug call you should do something like the following:

if (log.isDebugEnabled())
{
    log.debug("Some log message");
}

This stops unnecessary logging calls from happening and can improve performance. The check is not required though. If you don’t do it, your messages will still get filtered if the corresponding log level is not enabled. The check just stops an extra method call (and its parameters) getting added to the stack and any avoids any processing you do in building your log message, etc.

I tend to add this check only on log calls that either get called a lot (e.g. the body of a loop), or that have a lot of data to be logged (e.g. an array of values or a large object tree). Typically I don’t bother with this check for ‘error’ or ‘warn’ since they happen so infrequently, and I rarely bother with ‘info’ calls as well. Debug calls I usually do the check, and for trace calls I pretty much always use the check.

All of the above are just tips and suggestions. Logging is more a gut feel than a precise science. Define your own logging strategy to suit your needs – think about what you as a developer coming back to fix a bug in this code in three years time would want to see in the log file.

Step 3: Configure your loggers

Finally, we need to define a Log4J configuration file to format the log about and restrict the levels of log messages we are going to include in our log file. For this we simply add a file called ‘log4j.xml’ to src/main/resources of both the client and server modules.

src/main/resources/log4j.xml

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

    <appender name="console" class="org.apache.log4j.ConsoleAppender">
        <param name="Target" value="System.out"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="[%-5p %c{1}] - %m%n"/>
        </layout>
    </appender>

    <logger name="com.zenjava">
        <level value="debug"/>
    </logger>

    <root>
        <priority value ="info" />
        <appender-ref ref="console" />
    </root>

</log4j:configuration>

We’ve defined a single ‘appender’, which just logs to the console, and then we’ve set the root level of logging to ‘info’, which means only messages of ‘info’ and above will get logged. For our code however, we want to know more of what’s going on, so we’ve defined an additional logger for everything under ‘com.zenjava’ to show messages of ‘debug’ or above.

This configuration is very flexible, for a production environment you will likely want a rolling file appender and will also want to add different loggers and levels (e.g. you might want to enable Hibernate’s SQL logging to track database calls). You’ll find plenty of info on configuring Log4J for your specific needs on the web.

The full source code for this blog can be found at: http://code.google.com/p/jfxee/source/browse/trunk/first-contact/first-contact-logging/