Showing posts with label logging. Show all posts
Showing posts with label logging. Show all posts

Tuesday, December 20, 2011

Custom SLF4J Logger adapter

The Simple Logging Facade for Java or (SLF4J) is a simple facade for various logging frameworks. It decouples the logging framework from the application. The deployer can choose which logging framework to use. For every popular logging framework, an adapter Jar file is available. Deploy this file together with the core SLF4J Jar file, and the logging automagically works.

In my current work situation, a financial application I developed has to be integrated into an existing server application. This server application uses its own logging framework. Luckily, I've been using SLF4J, so logging integration is just a matter of writing a custom SLF4J adapter and replace the current adapter (SLF4J-Log4J) with it.

Writing an adapter is very easy. You only need to create three files:

  1. Create an implementation of the logger interface: org.slf4j.Logger
  2. Create a factory for the new logger using this interface: org.slf4j.ILoggerFactory
  3. Create your own binder class, so SLF4J knows which factory to use to get loggers: org.slf4j.spi.LoggerFactoryBinder
It is important to create these files in the package: org.slf4j.impl, because SLF4J is using this to find the correct adapter.

Firstly, we create the class that implements the SLF4J Logger interface. The implementation of this interface is used by SLF4J to delegate the logging. It's an interface with a large number of methods, so let the IDE generate the empty methods for you. Next is to implement the bodies of the methods to do the actual logging. In my case, I call the custom logging framework.

package org.slf4j.impl;

import org.slf4j.Logger;
import org.slf4j.Marker;
import org.slf4j.helpers.MessageFormatter;

public class MyLoggerAdapter implements Logger {
    // Bunch of inherited methods here. Let your IDE generate this.
    // Implement these methods to do your own logging.
}

Now, we create a factory implementation for the Logger class. This class is used to retrieve Logger objects used by the application. Make sure it implements the ILoggerFactory interface.

package org.slf4j.impl;

import org.slf4j.ILoggerFactory;
import org.slf4j.Logger;

import java.util.HashMap;
import java.util.Map;


public class MyLoggerFactory implements ILoggerFactory {
    private Map<String, MyLoggerAdapter> loggerMap;

    public MyLoggerFactory() {
        loggerMap = new HashMap<String, MyLoggerAdapter>();
    }

    @Override
    public Logger getLogger(String name) {
        synchronized (loggerMap) {
            if (!loggerMap.containsKey(name)) {
                loggerMap.put(name, new MyLoggerAdapter(name));
            }

            return loggerMap.get(name);
        }
    }
}

Finally, we need a way to register or bind the logger factory to SLF4J. To do that, we have to customize the StaticLoggerBinder class. You can almost use the same code provided by other adapters. I shamelessly ripped my code from the Log4J adapter.

package org.slf4j.impl;


import org.slf4j.ILoggerFactory;
import org.slf4j.spi.LoggerFactoryBinder;


public class StaticLoggerBinder implements LoggerFactoryBinder {

    /**
     * The unique instance of this class.
     */
    private static final StaticLoggerBinder SINGLETON
        = new StaticLoggerBinder();

    /**
     * Return the singleton of this class.
     *
     * @return the StaticLoggerBinder singleton
     */
    public static final StaticLoggerBinder getSingleton() {
        return SINGLETON;
    }


    /**
     * Declare the version of the SLF4J API this implementation is
     * compiled against. The value of this field is usually modified
     * with each release.
     */
    // To avoid constant folding by the compiler,
    // this field must *not* be final
    public static String REQUESTED_API_VERSION = "1.6";  // !final

    private static final String loggerFactoryClassStr
        = MyLoggerFactory.class.getName();

    /**
     * The ILoggerFactory instance returned by the
     * {@link #getLoggerFactory} method should always be the same
     * object.
     */
    private final ILoggerFactory loggerFactory;

    private StaticLoggerBinder() {
        loggerFactory = new MyLoggerFactory();
    }

    public ILoggerFactory getLoggerFactory() {
        return loggerFactory;
    }

    public String getLoggerFactoryClassStr() {
        return loggerFactoryClassStr;
    }
}

Compile and deploy this code together with the SLF4J jar, and logging will be handled by the our new adapter.

Links:

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.