Log4j Logging Guide


This article explains how to add logging to eXist-db using Log4j in Java code.


Logging may seem like a rather unimportant part of our application. After all, it consumes resources: programmer time, increasing class file size, CPU cycles, etc. All while doing nothing to provide end-user functionality. However, logging is an important part of any substantial body of software and is absolutely critical in enterprise software.

Customers have been complaining about our logging for quite some time. The logging system has made it hard to filter out the data of interest. It also doesn’t distinguish between important error messages, informational messages and debugging messages.

A big issue with the use of the logging system in troubleshooting is that it requires a restart for changes to the log configuration. Customers are often extremely reluctant to restart their production servers.

To amend these problems Log4j is introduced. Log4j is the most powerful Java-based logging library available today and is used by most of the application servers on the market.

Introducing Log4j

Log4j is based on the following core concepts:

  • Each log event is issued by a hierarchically named logger, e.g. xx.method.server.httpgw.

  • These hierarchical names may or may not correspond to Java class names.

  • All log events have an associated severity level (trace, debug, info, warn, error, or fatal).

  • To issue a log event programmers just acquire a logger by name and specify a log message and its severity level (and optionally a Throwable where applicable).

  • Logging is controlled by an administrator via a Log4j configuration file.

Based on these core concepts, Log4j provides a powerful set of functionalities:

Many “appender” choices

Each log event may be output to zero or more “appenders”. These are essentially generalized output pipes. Log4j output can be sent to the System.out/err, files, JDBC, JMS, syslog, the Windows event log, SMTP, TCP/IP sockets, telnet, etc. All this at the site administrator’s discretion.

File output includes various options for log rolling. For instance daily creation of new log files, segmenting when a given file size is reached, and externally controlled log rotation. These appenders can be run synchronously to the threads generating the log events or as separate asynchronous queues.

Flexible layout options

Each appender can specify a layout, for formatting the log message. The administrator can choose from HTML, XML, and various plain text formats – including the flexible PatternLayout, which allows selecting the data to include (timestamps, originating thread, logger name, etc.).

Hierarchical logger configuration

Administrators can configure log event cutoff levels and appenders for entire branches of the hierarchical logger tree.

For instance, by adding a console appender targeting System.out to the root logger, all Log4j output will go to System.out. One can configure the overall cutoff level as error at the root logger level so that only error and fatal messages are output, unless otherwise specified. One could then configure the xx.method logger to have an info level cutoff and an appender to capture all output to a specified file (in addition to System.out). These xx.method settings would then affect all loggers whose names begin with xx.method. (e.g. xx.method.server.httpgw).

Log viewers

Various free and commercial products provide specialized viewing capabilities for Log4j logs. Apache provides a very useful Log4j log viewer Chainsaw.

For more information visit the Log4j website website.

Java 1.4 and higher’s java.util.logging API is very similar to Log4j’s. However Log4j is much more powerful in a number of critical areas.

In conjunction with our JMX MBeans for Log4j, one can also:

  • Dynamically examine and reconfigure the Log4j configuration for the duration of the process via a JMX console.

  • Have all processes using a Log4j configuration file periodically check its modification date and automatically re-load it upon any change.

  • Force an immediate reload from a configuration file via a JMX console.

Using Log4j in new Java code

  1. Acquire a logger:

    import org.apache.Log4j.Logger; … private Logger logger = Logger.getLogger("xx.method.server.httpgw");


    • This is a somewhat time-consuming operation and should be done in constructors of relatively long-lived objects or in static initializers.

    • Many classes can separately acquire a logger using the same logger name. They will all end up with their own reference to the same shared logger object.

  2. Use the logger:

    logger.info( "Something I really wanted to say" );


    • info() is just one of Logger’s methods for issuing Log4j log events. It implicitly assigns the event a severity level of info and does not specify a Throwable. Logger methods for issuing log events include:

      public void trace(Object message); public void trace(Object message, Throwable t); public void debug(Object message); public void debug (Object message, Throwable t); public void info(Object message); public void info(Object message, Throwable t); public void warn(Object message); public void warn(Object message, Throwable t); public void error(Object message); public void error(Object message, Throwable t); public void fatal(Object message); public void fatal(Object message, Throwable t);
    • Note that in each case the message is an Object, not a String. If (and only if) Log4j decides to output the given log event (based on the configuration), it will render this object as a String (essentially via toString()).

It’s basicly as simple as that. You emit log events with appropriate log levels to appropriately named loggers. The Log4j configuration determines which appenders (if any) should output/record the event and how this should be done.

Converting existing logging code to Log4j

Conversion of existing logging code to Log4j can be as simple as replacing System.out.println() calls, etc, with use of the Log4j API. There are a few special considerations worth noting.

Dealing with Legacy Properties

You'll have to check the functionality of existing logging properties:

  • Sometimes they can be removed. For instance, usually properties specifying specific output files can be removed, as customers can now siphon Log4j output to specific files via Log4j’s configuration files.

  • It may be useful sometimes to preserve well known logging properties when people are used to these. The advice is then to ignore this property unless it is set to enable the given log – in which case it will ensure the given Log4j logger’s log level is verbose enough to cause the existing messages to be output. For instance, the existing code contains:

    private static final boolean VERBOSE_SERVER; static { XXProperties properties = XXProperties.getLocalProperties(); VERBOSE_SERVER = properties.getProperty("xx.method.verboseServer", false); } … if ( VERBOSE_SERVER ) System.out.println( "some message" );

    The static portions above can be left as is and the remainder changed to:

    import org.apache.log4j.Level; import org.apache.log4j.Logger; // place VERBOSE_SERVER declaration and static block from above here private static final Logger serverLogger = Logger.getLogger( "xx.method.server" ); static { if ( VERBOSE_SERVER ) serverLogger.setLevel( Level.ALL ); } … serverLogger.debug( "some message" );

    This example assumes that output from the given Log4j logger should be completely enabled when the existing property is set.

    One can also use this:

    if ( VERBOSE_SERVER ) if ( !serverLogger.isDebugEnabled() ) serverLogger.setLevel( Level.DEBUG );

    This causes the existing property to enable output from the given Log4j logger up through only a certain severity level, debug in this example.

    This approach to preserving existing “enabling” properties only keeps them working more or less as they were. The intended minimum log verbosity is ensured upon initialization but cannot be reset via the property without a restart. The ability to change the log-level on the fly or make fine grained log-level adjustments is only available through the Log4j configuration.

Conditional Computation of Data for Logging

Sometimes log messages are constructed conditionally, for instance like this:

if ( VERBOSE_SERVER ) // static final boolean { // various computations and assignment }

The if block may include System.out.println()’s or the results of the block may be used in later System.out.println()’s. The code is intended to avoid computations and assignments unless their results are used.

You can now use one of Log4j’s is*Enabled() methods for this. For example:

if ( serverLogger.isDebugEnabled() ) { // various computations and assignment that will only be used // if serverLogger.debug() calls }

The Log4j Logger class provides a set of methods for this:

public boolean isTraceEnabled(); public boolean isDebugEnabled(); public boolean isInfoEnabled(); public Boolean isEnabledFor(Level);

Configuring Log4j

The Log4j.xml configuration file controls Log4j’s behavior.

It is used mainly to set a given level of log output for loggers. Without such configuration only ERROR and FATAL log events will show up. Therefore you have to change the configuration to see trace, debug, info, or warn log events in the Log4j output.

To turn on a given logging level for all loggers, find the Log4j.root property and change its priority value to the desired level. For instance:

<root> <priority value="debug"/> <appender-ref ref="exist.core"/> </root>

Change the priority level to info to see informational messages:

<root> <priority value="info"/> <appender-ref ref="exist.core"/> </root>

This will result in a cacophony of log output, so you’ll generally want to adjust the logging level to a more specific level. For instance:

<category name="org.exist.security" additivity="false"> <priority value="info"/> <appender-ref ref="exist.security"/> </category>

This sets the org.exist.security logger’s level to info.

Note that doing this causes the default log level of all org.exist.security loggers to be set to info. For example, the level of the org.exist.security.xacml logger would also be set to info, unless of course the level for this logger is specified explicitly.

Checking the Log4j configuration file is done periodically so changes may go unnoticed for a few minutes.

To make temporary changes to the Log4j configuration without changing the configuration files, use JMX MBeans:

  1. Start jconsole

    jconsole is located in the Java SDK’s bin directory. You can either double-click on it or run it from the command line.

  2. Select the target JVM

    jconsole will list the Java processes running on your machine under the current user, which have been configured to allow local JMX connections.

  3. Navigate to the Logging node in the MBean tree:

    • Select the MBeans tab.

    • Expand the right folder.

    • In the servlet engine expand the WebAppContext folder and the folder named after your web app.

    • Select the Logging node (which should now be visible).

  4. Perform desired operations and/or modifications:

    • To change the configuration file check interval, change the ConfigurationCheckInterval attribute to the desired number of seconds. Note that this change will apply only for the duration of the JVM process unless you select the Loader node and its save operation.

    • To force an immediate reload of the configuration file, press the reconfigure button on the operations tab.

    • To examine other aspects of the configuration and make temporary changes, press the registerLoggers button on the operation tab. Expand the Logging tree node and examine/operate upon its children.

Tips and Tricks


Carefully select appropriate logger names

Logger names should be meaningful and facilitate hierarchical configuration by administrators. Use a namespace prefix, either xx or com.xxx to avoid collision with logger names from 3rd-party libraries and customizations.

For instance, one might have xx.method.server for general logging related to various low-level aspects of the method server and xx.method.server.timing for logging specifically related to the method timing. Use Java class and package names where these make sense.

Document your logger if appropriate

If appropriate, document your logger in /xxx/src_web/loggers.html. For instance when the output is of interest to your customer. The logger should be documented (by name) in /xxx/src_web/loggers.html (which ends up in xxx’s codebase in an installation).

Select appropriate levels for log events

One of the big advantages of Log4j is that each logging event has an associated level. An administrator can now filter log messages by level. The following table delineates when to use each level.




Very low-level debugging “execution is here” debugging/troubleshooting messages.


Messages of interest to those debugging or troubleshooting (with greater importance than trace messages). Probably only meaningful to developers


General informational messages. Understandable by and/or of interest to non-developers as well.


Warnings of potential problems


Error conditions


Fatal error conditions, For instance a shut down, a likely crash or something equally severe

Don’t go overboard with the Log4j configuration files

Log4j provides a great deal of ease and flexibility in its configuration. Its log viewers also make it easy to merge log data from multiple Log4j logs or filter out the data of interest from a general purpose log. Given this it makes little sense to provide a complex Log4j configuration file. The customer can change the configuration to have more or less specific log outputs as dictated by their needs and desires.

Adjust log levels in Log4j configuration files where appropriate

The default for xxx is to output error and fatal log messages. This generates relatively "quiet" logs that only alert administrators to issues. There are however sometimes log messages classified as informational that should be output at this log level as well. Examples include periodic information like summaries of requests serviced by the server over a time interval and process health summaries" For this extend the Log4j configuration to enable info level debug output for the logger in question.

Don’t include redundant data in log messages

Administrators can easily configure Log4j log output to efficiently include current time, thread name, logger name, evernt level, etc. Log4j includes this information in a standard, structured fashion so it is easily interpreted by log viewers like Chainsaw. Inclusion of any of these pieces of information in the log message itself is therefore redundant and pointless.

make use of AttributeListWrapper where appropriate

For some particularly significant logs it is important to give the administrator even more control, including:

  • Allowing them to select which attributes should be included in a given log message

  • Allowing them to specify the order of these attributes

  • Allowing them to specify the formatting of these attribute (e.g. comma delimited, with or without attribute names, etc)

Examples of such cases include request access and periodic statistics logging.

There is a re-usable utility for just this purpose, xx.jmx.core.AttributeListWrapper.

Don’t be afraid to use Log4j in any tier or JVM

Log4j currently is not included in the client jar set. The only reason for this is that currently no clients use Log4j. However, if the log4j.jar is needed in the client simply include it in the client's jar set. Java’s Pack200 technology reduces jars to 25% their original size on average.


The operation of Log4j’s Logger class’s logging methods for issuing log events can be summed up as:

public void log( Level level, Object message ) { if ( isEnabledFor( level ) ) { String string = render( messasge ); for ( Appender appender : myAppenders ) appender.output( string ); } }
  • render() is simply a toString() call, except when message is an instance of a class for which a specialized render has been registered.

  • trace(), debug(), info(), warn(), error(), etc, call log() with the appropriate level.

Note that Log4j's documentation claims that isEnabledFor(), and the Logger.is*Enabled() method are extremely fast. Therefore log() should take very little time as well (unless isEnabledFor() returns true).

Given this, a few additional performance tips and tricks:

Don’t reacquire a logger on each usage

AThe LogR.getLogger() (and underlying Logger.getLogger()) calls are relatively expensive. One should acquire these objects once per class (or once per instance of a class) and re-use them in subsequent logging calls.

Don’t assume a log’s level cannot change

One of the big advantages of Log4j is that administrators can easily change the level setting of any logger at any time. One can however easily undo this by following conventions common in existing logging code, e.g.:

static boolean LOG_ENABLED = logger.isInfoEnabled (); … public void someMethod() { if ( LOG_ENABLED ) logger.info( … ); }

Logger’s isEnabledFor() and is*Enabled() routines are fast enough to allow calling them more frequently in order to obtain the benefits of dynamically configurable logging levels.

Don’t check whether the log level is enabled before every log call

Do not write code as:

if ( logger.isDebugEnabled() ) logger.debug( "Some constant string" );

This results in essentially no savings when isDebugEnabled() is true. It also makes the code more verbose and harder to read. Instead do:

logger.debug( "Some constant string" );
Do avoid doing additional work for logging unless the logger is enabled

Assume the last example looked like:

if ( logger.isDebugEnabled() ) logger.debug( "Object " + object.getDisplayIdentity() + " is being deleted" );

Then the isDebugEnabled() check should be performed. In this case, two string concatenations and a potentially (somewhat) expensive method call can be saved when the logger is not debug enabled. See the “Conditional Computation of Data for Logging” section above for another example of this pattern.

On the other hand, this technique should not be used when you are all but certain the given logger will be enabled. Usually this applies only to log events being emitted with an error or fatal level. In this case saving times for the few cases in which someone has actually disabled this level of logging is not worthwhile.

Another technique to avoid unnecessary work is to leverage the fact that Logger’s take objects, not strings, as arguments. Thus one might write:

SomeClass someObj = new SomeClass(…); logger.info( someObj );

Here one will pay for the construction of someObj in all cases but will only pay for someObj.toString() when logging is enabled for info-level log events. Thus if very little work is done in the constructor and most is done in toString() this avoids doing work except when necessary. AttributeListWrapper (see above) is an example of this technique.

Hoist log level checks outside of very tight loops

For cases where a given log level will usually not be enabled, for instance for trace and debug log messages, one should avoid repeated checks within a tight loop. For example:

{ final boolean traceEnabled = logger.isTraceEnabled(); for ( int ii = 0; ii < n; ++ii ) { // do some very quick stuff if ( traceEnabled ) logger.trace( ... ); // do a little more very quick stuff } }

Trace level logging is rarely enabled and so in this example checking for this case ahead of time can save us from repeatedly verifying this in a tight loop. This does, however, come at the cost of making it impossible to dynamically enable trace logging for this logger in the middle of this loop. Due to this, this technique should only be used for tight loops where the duration of the execution represented by the loop (and thus the time during which the logging behavior may lag the intended setting) is small.