Showing posts with label log4j. Show all posts
Showing posts with label log4j. Show all posts

Saturday, July 16, 2011

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 EnumCommons LogLog4JJDK 1.4 LoggerLogKit
FATALFATALFATALSEVEREFATAL_ERROR
ERRORERRORERRORSEVEREERROR
WARNWARNWARNWARNINGWARN
INFOINFOINFOINFOINFO
DEBUGDEBUGDEBUGFINEDEBUG
DEBUGDEBUGDEBUGFINERDEBUG
TRACETRACEDEBUGFINESTDEBUG


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!

Saturday, September 25, 2010

Apache log4j

Apache log4j is a very popular framework for building logging facilities in Java applications. Logging is essential in debugging, localizing problems, and security auditing. Logging statements in the application do not have to be removed when the application is finished for deployment, and will not influence performance.

Log4j is an hierarchical logger, and has 6 logging levels to control/grade logging messages:

  1. TRACE
  2. DEBUG
  3. INFO
  4. WARNING
  5. ERROR
  6. FATAL

The list is ordered by importance, where the last level is the highest in hierarchy. The current log level and hierarchy determine what to log. When a certain log level is used in an application, all lower ranked log statements are also logged. Example: when the current log level is WARNING, all lower log statements like: TRACE, DEBUG, and INFO are logged. But when the log level is TRACE, no other log level messages will be printed, because the DEBUG level is the lowest log level. Log level can be changed during run-time.

Another control mechanism for hierarchical logging, is that classes/objects of the application obtain a logger separately attached to its class hierarchy. Like the statement below in the constructor of Foo.class.

Log log = Logger.getLogger(Foo.class);

This way, you can configure the logger to print log messages of a selection of classes only. You can use the root logger to print log messages from all classes, or use a class specific logger to print only message from this class and/or its children.

Apache log4j can be configured in two ways:

  1. Using property files (example: log4j.properties)
  2. Using XML files (example: log4j.xml)


I prefer the properties file way, because it's less verbose. We can configure many things in the configuration file, like:

  • output log file
  • log file name pattern
  • initial log level
  • log line format
  • log file management


Example application
Let's create an example application that uses Apache log4j:

package test;

import org.apache.log4j.Logger;

public class LogMain {
private Logger log;

public static void main(String[] args) {
LogMain app = new LogMain();
app.run();
}

public LogMain() {
System.out.print("Application started.\n");
this.log = Logger.getLogger(LogMain.class);
}

public void run() {
this.log.trace("TRACE message!");
this.log.debug("DEBUG message!");
this.log.info("INFO message!");
this.log.warn("WARN message!");
this.log.error("ERROR message!");
this.log.fatal("FATAL message!");
}
}

To configure Apache log4j, you can use a properties file or an XML file. The properties file looks like this:

log4j.rootLogger=INFO, CONSOLE, FILE

log4j.appender.FILE=org.apache.log4j.DailyRollingFileAppender
log4j.appender.FILE.File=logs/app.log
log4j.appender.FILE.datePattern=yyyyMMDD.
log4j.appender.FILE.Append=true
log4j.appender.FILE.layout=org.apache.log4j.PatternLayout
log4j.appender.FILE.layout
.conversionPattern=%d{HH:mm:ss:SSS} - %p - %C{1} - %m%n

log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender
log4j.appender.CONSOLE.layout=org.apache.log4j.PatternLayout
log4j.appender.CONSOLE.layout
.conversionPattern=%d{HH:mm:ss:SSS} - %p - %C{1} - %m%n

The equivalent XML-file is this:

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

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

<appender name="file"
class="org.apache.log4j.DailyRollingFileAppender">
<param name="file" value="logs/app.log" />
<param name="datePattern" value="yyyyMMDD." />
<param name="append" value="true" />
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern"
value="%d{HH:mm:ss:SSS} - %p - %C{1} - %m%n" />
</layout>
</appender>

<appender name="console"
class="org.apache.log4j.ConsoleAppender">
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern"
value="%d{HH:mm:ss:SSS} - %p - %C{1} - %m%n" />
</layout>
</appender>

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

</log4j:configuration>

Put the file in the class path, and Apache log4j will automatically find and load it.

The example configuration uses two log appenders that define the output of logging messages:

  1. DailyRollingFileAppender: automatically rotates logs every day
  2. Console: prints to console

The output can also be customized by the layout class, which is configured to use a conversion pattern to format the output. The output of the example is formatted like this:

19:23:54:938 - WARN - LogMain - WARN message!

This blog post gives you enough information to start using Apache log4j. For more information you can also read the manual here.

Extra note
When using Apache log4j for applications in containers (web and EJB), it might clash with the logging used by the container. For example: Oracle Application Server (OAS) also uses Apache log4j for its application server logging, and will not deploy applications that bundle Apache log4j. This problem can be circumvented by disabling the library apache.commons.logging for deployment.