Some tips for application logging in Java

Some tips for application logging in Java

In this blog post I want to share some of my thoughts about application logging in Java. Hopefully, you'd find them useful!

1. Consistent use of logging levels

Have a good understanding of the available log levels, and make sure you use them consistently throughout the application. Especially, if you're using the old JDK 1.4 Logger framework. What is the difference between FINER and FINEST?

Below is an abstract list of common log levels and a description of when to use them. This list is based on the Log4J log levels, but can be mapped to other logging frameworks.

FATAL
Unrecoverable errors. Leads to termination of the process (or a crash). Example: the application is in a corrupt state, and has no clue how to restore state.

ERROR
Errors that are not recoverable, but application can continue running. Example: an user request could not be executed, because some inputs are missing or invalid.

WARN
Undesirable or unexpected situations, but not necessarily "wrong". Example: the application expects a value in the cache, but could not find it. The application attempts to get the value in another way. Or a network connection is broken. The application tries to recover by reconnecting.

INFO
Important but normal run time events useful for monitoring. Example: a business process is finished.

DEBUG
Detailed information useful for debugging the system. Example: the content of a variable is printed in strategic locations of the application.

TRACE
Detailed control flow information. Example: a method is called message.

Below is a mapping of log levels of different logging frameworks. Levels that have the same level of severities are placed on the same row.

Carbon Severity Enum	Commons Log	Log4J	JDK 1.4 Logger	LogKit
FATAL	FATAL	FATAL	SEVERE	FATAL_ERROR
ERROR	ERROR	ERROR	SEVERE	ERROR
WARN	WARN	WARN	WARNING	WARN
INFO	INFO	INFO	INFO	INFO
DEBUG	DEBUG	DEBUG	FINE	DEBUG
DEBUG	DEBUG	DEBUG	FINER	DEBUG
TRACE	TRACE	DEBUG	FINEST	DEBUG

2. Proper error logging

Error logging should not be done at the location where an exception is thrown, but at the location where the exception is handled to prevent double logging.

public void doSomething() throws ACheckedException {
 if (someErrorCondition) {
     String errorMessage = "Hey, some error occurred.";
     logger.error(errorMessage);
     throw new ACheckedException(errorMessage);
 }
}

public void callerMethod() {
    try {
     doSomething();
    } catch (ACheckedException exception) {
        logger.error(exception.getMessage());
        doSomethingElse();
    }
}

The code above will log the same error twice. The log statement in the first method can be removed. Exceptions should "bubble up" to the method of the class that can handle the error, and then be logged. In most cases this class will play the controller role in a MVC style application.

3. Prevent unnecessary string concatenations

SLF4J is considered by many the best Java application logging framework. It's a logging facade that masks existing logging frameworks, which can be determined at deployment time. A great feature is that SLF4J allows you to avoid unnecessary string concatenation, which is really expensive.

    logger.error("The error '" + errorMessage +
                 "' occurred in the " +
                 component.getName() + " component.");

Of course, you can use logging guards like this:

    if (logger.isEnabledFor(Level.ERROR) {
        logger.error("The error '" + errorMessage +
                     "' occurred in the " +
                     component.getName() + " component.");
    }

But this will clutter your code, and degrades code readability.

The SLF4J way looks like this:

    log.error("The error '{}' occurred in the {} component.",
              errorMessage, component.getName());

As you can see, the use of SLF4J makes the logging statement more readable, and SLF4J will not compile the log message when the message will not be logged (i.e. not running in a high enough log level).

4. Use complete logging messages

Read logs, and check that the information in the log messages is complete, and can be used to reverse engineer back to the original state of the system.

01/02/2011 ERROR The user has a missing property.

The log message above could be improved by adding: the identifier for the user, and the name of the property, so it's easier to understand (and recreate) the situation that caused the log message. Another improvement is to add a message that gives information about what will happen next.

If you also have tips or views about application logging in Java, please don't hesitate to share them in the comments!

Restarting a Java application programmatically

I found an interesting article through DZone (excellent site) about how to start a Java application programmatically. The original article can be found on the blog of Leo Lewis. Restarting a Java application is pretty useful for certain applications, where you don't have direct access to the deployment environment.

Here is the orginal link to the article:
http://leolewis.website.org/wordpress/?p=499

Mocking classes with JMock

Normally, you'll get the following exception when you try to mock a class with jMock:

java.lang.IllegalArgumentException:
  com.javaeenotes.YourClass is not an interface.

The solution is to use the ClassImposteriser when instantiating the Mockery class.

context = new Mockery() {
  {
    setImposteriser(ClassImposteriser.INSTANCE);
  }
};

Now you can mock any class, just as interfaces. The complete instructions can be found on this web page.