Tuesday, 7 October 2008

Logging on application servers – java.util.logging with log4j together

Logging seems quite an easy task. However, from my experience I know that not all Java programmers fully understand it. There are lot of different libraries on the market to choose from – log4j, java.util.logging (JUL, or Jdk14 logging), commons-logging, slf4j and some others. Although large choice of libraries seems generally a good thing it is a pain in case of logging. I'll explain why.

I got a task at work to choose a logging framework for our application. My first idea was to take the framework that was already used by third-party libraries being part of our application. Thanks to this all logs could be aggregated together and we would have one-place logging configuration. This would mean, for instance that our application's logs would be written together with SQL queries logged by Hibernate. This would enable easy debugging. The opposite situation when application logs are in a different file then Hibernate logs isn't very convenient. It quickly appeared that it wasn't possible to use the same logging framework as our libraries did because libraries used different logging frameworks. Log4j is used by default by JBoss and one of our in-house modules, JUL by JSF-RI, Facelets, JAXB and CXF. Quartz, Spring and RichFaces use commons-logging. Hibernate switched to slf4j. Luckily there was a solution – routing log entries from one logging framework to another.

Logging on JBoss, make JUL working

By default JUL writes all logs to System.err (see JRE_HOME/lib/logging.properties). It means that if you use a Logger object created by JUL your log entries will be just printed to the console. Luckily JBoss intercepts System.err and dumps it through its internal logging system to the server.log file. JBoss by default uses log4j and is configured through jboss-log4j.xml. Thanks to this all logs produced by JBoss and the deployed applications are put to the same place. The only problem is that all JUL logs are treated by JBoss's log4j as plain text:

12:15:01,820 ERROR [STDERR] 04-Jan-2008 12:15:01 com.sun.facelets.compiler.TagLibraryConfig loadImplicit
INFO: Added Library from: jar:file:...

The first part is produced by log4j and the rest by JUL. As you see it's impossible to use jboss-log4j.xml to filter JUL logs based on level (priority) or category. That's because JBoss treats all data printed to System.err as an ERROR in the STDERR category. This means we can't make the proper use of the original level (INFO) and category (com.sun.facelets.compiler.TagLibraryConfig).

JUL can be only configured globally at the JVM level. There is no way of per-classloader configuration like for log4j. You can either override the default JUL configuration by specifying a file accessible through the file system or programmatically. File configuration isn't appropriate for the Java EE environment. The best solution to configure JUL is to use the JBoss service as described by Shrubbery. Shrubbery also provides ready-to-use handler that redirects JUL to log4j. In this solution JUL redirecting handler is registered when the application EAR starts and unregistered when EAR stops. Unregistering is needed to remove a class dependency from JUL to log4j appenders loaded from the EAR. As long as the handler class is registed in JUL the garbage collector cannot clean it.

After applying the Shrubbery's handler the logs looks appropriate with levels and categories are preserved:

14:18:03,490 INFO [faces.compiler] Added Library from: jar:file:…

With redirecting in place there is no need to touch JUL configuration. All setup can be done in one place – jboss-log4j.xml. This applies to configuration of appenders, priorities, etc. Because jboss-log4j.xml is kept out of the application EAR each developer may have their own configuration to debug specific parts of the system.

After making all logs coming to the same place we decided that for our project there is no much difference what logging API to use. In this case let’s use JUL because it’s a JDK standard. There were no important functional differencies that justified choosing something non-standard. Adhering to standard reduces number of libraries we depend on.

Logging on WebSphere, make log4j working

WebSphere 6 internally uses JUL. Thanks to this all logs reported with JUL API are stored properly in SystemOut.log. The correct level and category is preserved. This is also the case for commons-logging. It seems that WebSphere automatically reconfigures commons-logging to use JUL. This happens even if log4j is on the classpath which normally switches commons-logging to log4j. Slf4j can be easily set up to use JUL which is very reasonable for WebSphere. The only framework that needs attention is log4j.

Routing log4j to JUL is easier than routing vice-versa. That's because it's easy to have per-classlaoder configuration of log4j. To configure redircting it is needed to add log4j.properties to the EAR's classpath and write a log4j appender.

The log4j.properties that work for me are here:
log4j.appender.JUL=se.sync.util.logging.JulLog4jAppender
log4j.logger.se.sync=ALL,JUL
log4j.additivity.se.sync=false
I tried make it working with it working with reconfiguring the rootLogger instead of se.sync logger but it didn't work. I don't know exactly why but it seems that WebSphere registers a root appender when log4j is used and this causes duplicate log entries. To eliminate this both appender and additivity have to be set on a non-root logger. Here is the code for the log4j appender.
package se.sync.util.logging;
import java.util.HashMap;
import java.util.Map;
import java.util.logging.Level;
import java.util.logging.LogRecord;
import java.util.logging.Logger;

import org.apache.log4j.AppenderSkeleton;
import org.apache.log4j.spi.LoggingEvent;
import org.apache.log4j.spi.ThrowableInformation;

/**
* @author karol.bienkowski on 30 Sep 2008
*/
public class JulLog4jAppender extends AppenderSkeleton {

private static final Logger log = Logger.getLogger(JulLog4jAppender.class.getName());

private static final Map<org.apache.log4j.level, Level> LEVEL_MAP =
new HashMap<org.apache.log4j.level, Level>();

static {
LEVEL_MAP.put(org.apache.log4j.Level.OFF, Level.OFF);
LEVEL_MAP.put(org.apache.log4j.Level.FATAL, Level.SEVERE);
LEVEL_MAP.put(org.apache.log4j.Level.ERROR, Level.SEVERE);
LEVEL_MAP.put(org.apache.log4j.Level.WARN, Level.WARNING);
LEVEL_MAP.put(org.apache.log4j.Level.INFO, Level.INFO);
LEVEL_MAP.put(org.apache.log4j.Level.DEBUG, Level.FINE);
LEVEL_MAP.put(org.apache.log4j.Level.TRACE, Level.FINER);
LEVEL_MAP.put(org.apache.log4j.Level.ALL, Level.ALL);
}

@Override
protected void append(LoggingEvent event) {
LogRecord record = new LogRecord(extractLevel(event), extractMessage(event));
record.setLoggerName(event.getLoggerName());
record.setMillis(event.timeStamp);
record.setThrown(extractThrown(event));
log.log(record);
}

private Level extractLevel(LoggingEvent event) {
org.apache.log4j.Level level = event.getLevel();
Level ret = LEVEL_MAP.get(level);
return ret != null ? ret : Level.ALL;
}

private String extractMessage(LoggingEvent event) {
Object message = event.getMessage();
return message != null ? message.toString() : null;
}

private Throwable extractThrown(LoggingEvent event) {
ThrowableInformation info = event.getThrowableInformation();
return info != null ? info.getThrowable() : null;
}

public void close() {
// nothing to do
}

public boolean requiresLayout() {
return false;
}

}
The other trick is to put log4j configuration into a separate JAR. An EAR's classpath specified in the MANIFEST.MF file can contain of JARs only so I packed my log4j.properties into a one-file log4j-config.jar.

To illustrate how it works take a look at a sample of misconfigured logs on WebSphere:

[9/30/08 10:33:07:848 CEST] 0000003f SystemOut O 10391 [SoapConnectorThreadPool : 18] INFO org.hibernate.cfg.Environment - Hibernate 3.3.1.GA

and then after setting it correctly (slf4j with JUL):

[10/1/08 9:31:45:167 CEST] 0000008b Environment I org.hibernate.cfg.Environment Hibernate 3.3.1.GA



1 comment:

Joshua said...

Thanks for trying out my juli->log4j bridge! (Josh, operator of 'shrubbery').

As a side note, JBoss AS 5 already has something like this built in.