Turnleaf Design Ramblings of a junior developer

Log4j 4 Enterprise

Logging is an important part of any application. Logging provides debugging information, the state of the application, and a record of what happened when the application failed. As applications increase in size so does the demands and complexity of logging. Without a proper logging system it can become difficult to determine from where in an application a log statement is being executed and without an easy way of changing logging behavior it can have a negative effect on an application's performance.

The Apache Foundation maintains the log4j project which is an easy to use system that provides a large array of really cool features for logging. This tutorial, part of my dev environment series, is an introduction into using log4j in an enterprise setting. Topics that I will cover include; implementing log4j in a project, customizing the log statement, usage of appenders, creating loggers and logger inheritence,  and setting up log4j to work on an application server. This will cover many of the basic needs of enterprise logging.

A few simple steps before we begin...

As with all my tutorials that involve coding you can download the source code here. In this example I will be using the project HttpExample, starting on revision 24. If you want to work on this code locally you will also need the log4j library which can be found here, and then add it to your project's classpath by right clicking on your project > build path > add external libraries and then navigate to the library's location (if you are using eclipse).

Log4j, it's better than bad, it's good!

Implementing log4j in a project is surprisingly simple. I already covered the first step of adding log4j to the project's classpath. The second step is setting up the configuration file. If you look in the project you will see I already created one, log4j.xml, which looks like this:

<?xml version="1.0" encoding="ISO-8859-1"?>
<!DOCTYPE log4j:configuration SYSTEM "/log4j.dtd">

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

<appender name="simpleAppender" class="org.apache.log4j.ConsoleAppender">
<layout class="org.apache.log4j.SimpleLayout" />
</appender>

<root>
<appender-ref ref="simpleAppender" />
</root>

</log4j:configuration>

The final step is to add a logger to a class and log statements, which I have also already done so in NewUserFormController:

com.tld.form.controller.NewUserFormController

public final class NewUserFormController {
private static Logger LOG = Logger.getLogger(NewUserFormController.class);

...

protected static String createUser(UserFormBean bean) {
LOG.trace("trace");
LOG.debug("debug");
LOG.info("info");
LOG.warn("warn");
LOG.error("error");
LOG.fatal("fatal");

...

}

In a previous article I created some unit tests for this project, if you try running one of the unit tests under TestNewUserFormController the following should be printed to the console:

DEBUG - debug
INFO - info
WARN - warn
ERROR - error
FATAL - fatal

Not much more advanced than using the standard system.out. There seems to be a problem however, one of the log statments, LOG.trace("trace");, was not printed to the console. This actually is not a problem and brings me to the first feature of log4j I will go over.

Not all log statements are created equal

All applications more or less go through the loosely defined stages of; development, qa testing, and finally production. The demands of logging change as much as what occurs in each of these stages. In response to these demands log4j offers six default levels of logging (from lowest to highest); trace, debug, info, warn, error, fatal, these levels give developers relatively fine grained control of which log statements are executed. This aids developers by allowing us to change the amount of logging an application is executing easily and without making a binary change.

To change the logging level of our application we will need to go into the configuration file and add a "level" tag within our "root" tag. Within this tag is the attribute "value" which we set with the minimum level at which to begin logging. So if we set the level to "debug" (the default) all log statements of the level of "debug" or higher will be executed. Here is an example:

<root>
<level value="trace" />
<appender-ref ref="simpleAppender" />
</root>

With the logging level set to trace, if we run one of the unit tests again all six statements should appear.

Customizing the logging message

So log4j has given us control over which statements are printed, currently we are using the SimpleLayout which, though quick, doesn't offer a lot of information about the statements being printed. Log4j offers the PatternLayout class which gives the developer a wide degree of latitude in customizing his log statements. Lets get our feet wet with this system by adding a timestamp and the fully qualified name and line number to our log statements. Open up log4j.xml again and make the following changes to the appender tag:

<appender name="simpleAppender" class="org.apache.log4j.ConsoleAppender">
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{MMM-dd HH:mm:ss} %p %l - %m%n" />
</layout>
</appender>

Run an unit test and the output should look something like this:

Sep-29 00:39:33 TRACE Sep-29 00:45:57 TRACE com.tld.form.controller.NewUserFormController.createUser(NewUserFormController.java:18) - trace

Definitely a lot more useful as we know exactly where the statement is being executed from and when the statement was executed (not particularly useful here, but absolutely necessary for a deployed application). There is a lot more options for customization, for more information check out this link. It's important to consider the performance impact modifications may have as well, adding the fully qualified name to a log statement has a significant performance impact. The link above notes if an option has a significant impact on performance.

Appender? I barely knew her!

Right now all of our log statements are printed out to the console. This is great for when debugging in an IDE, but eventually we will deploy this application to the server and we don't want these log statements to be sent to the standard server log. A lot of information is already dumped to this log and if we deploy multiple applications to a server it would be very difficult to differentiate which application is printing what statement. Again log4j comes through by making it simple to change where a log statement is printed. Again open up log4j.xml and add the following lines (note this is a new appender tag):

<appender name="fileAppender" class="org.apache.log4j.FileAppender">
<param name="File" value="myLogFile.log" />
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{MMM-dd HH:mm:ss} %p %l - %m%n" />
</layout>
</appender>

Then add the appender to the root tag like so:

<root>
<level value="trace" />
<appender-ref ref="simpleAppender" />
<appender-ref ref="fileAppender" />
</root>

Finally rerun one of the unit tests, refresh your project and you should see a file titled "myLogFile.log" with the log statements contained within.

Clearly this is an unorthadox (and not particularly useful) way of handling logging. Later in this tutorial we will send this output to a more reasonable location, but for now on to loggers.

Setting up separate logs and logger inheritence

So far we have been using the root logger (the root tag in the log4j.xml file). For a small application with few dependencies like I am demonstrating, it is difficult to show the issues that arise from only using the root logger. As an application increases in complexity it often pulls in additional libraries, just like a developer may setup step filters in a debugger to ignore portions of an application or libraries he doesn't care about, we can setup loggers to ignore log statements from certain parts of an application or direct log statments to a different location. Lets explore this practice as best we can, given the limitations of this example, once again open up log4j.xml remove the "root" tag and make the following changes:

<logger name="com.tld.form">
<level value="trace" />
</logger>

<root>
<level value="error" />
<appender-ref ref="simpleAppender" />
</root>

If you run an unit you will see the output was the same as before. Now go add couple of log statements to UserDaoImpl like so:

public class UserDaoImpl implements UserDao {

private static final Logger LOG = Logger.getLogger(UserDaoImpl.class);

@Override

public boolean doesUserExist(UserFormBean bean) {

LOG.debug("Debug");
LOG.error("Error");
...
}
...
}

Again run the unit test and you will see these two log statements added to the original six. Now go back into log4j.xml and add the following:

<logger name="com.tld.form.dao">
<level value="error" />
</logger>

Rerun the unit test and you will see only the "error" log statement was printed from with in UserDaoImpl.

There are two important and closely related concepts shown in the examples above; logger retrieval and logger inheritance:

1. The way I have been retrieving logger by passing the class is the industry standard. When you call "Logger.getLogger(class)" log4j checks its list of declared loggers and returns the closest ancestor to the passed in name, if none are found than the root logger is returned. Above the logger for the class "NewUserFormController" uses logger "com.tld.form" because its logger name is "com.tld.form.controller.NewUserFormController" where as the the class "com.tld.form.dao.UserDaoImpl" uses the logger"com.tld.form.dao" because that is its closest ancestor.

2. Just like Java offers inheritance so a developer can reuse attributes in like ancestor classes, log4j supports inheritance for the same reason. In the above example we didn't have to redefine an appender for loggers "com.tld.form" and "com.tld.form.dao" because both inherited the appender from the root logger (which all loggers inherit from). Also like in Java attributes inherited from a more recent ancestor override those of an older ancestor. For a more in depth explanation of how inheritance works check here.

Server?! I barel... never mind

So log4j is working all fine and dandy in Eclipse, but eventually we will move this application to a server and we will still want logging to take place. To do this right we will have to make several changes.

The first change is correcting a mistake I made earlier which involves the location of the log4j config file. One of the strengths of log4j is the ability to make a change to the logging behavior of an application without making a binary change (the change does not involve recompiling and redploying code). While not absolutely necessary we will want to move the log4j out from under the src folder and create a new folder called "resources" and place it in here. This will show other developers that log4j.xml is a separate deployable from the source code.

[Note: you will also want to include a copy of log4j.xml under test, so logging can still take place while running unit tests]

Since log4j is no longer on the classpath of our project we will need to tell our application where to find the configuration file out on the server, however this should only happen once and at application start up. To do this we will need to create a servlet listener. If you look under com.tld.form, you will see I already wrote one:

public class LoggerListener implements ServletContextListener {
private static final String LOG4J_CONFIG = "log4jConfig";

@Override
public void contextDestroyed(ServletContextEvent arg0) {
}

@Override
public void contextInitialized(ServletContextEvent arg0) {
DOMConfigurator.configure(arg0.getServletContext()
.getInitParameter(LOG4J_CONFIG));
}
}

A servlet listener is hook for a developer to run actions during an application start up or shut down ( contextInitialized and contextDestroyed respectively). They are quite handy in scenarios like this where you need to load global properties or configure something. Also I didn't cover this before, but there are two formats to log4j configuration files, in this tutorial we covered using the xml format, but there is also the properties format which is a text file that follows a specific syntax. This information is significant because if you are using the former like we are you will need to use DOMConfigurator, if you are using the latter however you will need to use PropertyConfigurator to configure log4j.

Next we need to update our web.xml to tell it we have a listener and to give the location of the log4j.xml file.

<web-app>
...
<context-param>
<param-name>log4jConfig</param-name>
<param-value>/etc/glassfishv3/glassfish/domains/domain1/config/log4j.xml</param-value>
</context-param>
<listener>
<listener-class>com.tld.form.LoggerListener</listener-class>
</listener>
...
</web-app>

The "context-param" element tells the listener where the log4j.xml file is located on the server. The listener tag is obviously designating a class in the project as being a servlet listener. Location of elements matter in a web-xml, so put these elements near the top of your web.xml file.

Next we will need to make a change to the build file. Since we are now referencing log4j classes in our application we will need to make sure these classes are available on the classpath of our application when we deploy it to the sever. To do this go into the build.xml file and add the "lib" tag to the war tag like so:

<target name="war" depends="compile">
<war destfile="${build}/war/${ant.project.name}.war" webxml="webapp/WEB-INF/web.xml">
<fileset dir="webapp" includes="*.jsp" />
<classes dir="${build}/classes"/>
<lib dir="${libs}">
<include name="log4j-1.2.16.jar" />
</lib>
</war>
</target>

Now when we build the project the log4j library will be included within the distributable (the ear file).

Finally we will need to update the log4j.xml under the resources folder to get setup handle logging in a server environment. I made the following changes:

<?xml version="1.0" encoding="ISO-8859-1"?>
<!DOCTYPE log4j:configuration SYSTEM "/log4j.dtd">

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

<appender name="fileAppender" class="org.apache.log4j.FileAppender">
<param name="File" value="/etc/glassfishv3/glassfish/domains/domain1/logs/HttpExample.log"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{MMM-dd HH:mm:ss} %p - %m%n&lt;EOR&gt;%n" />
</layout>
</appender>

<root>
<level value="error" />
<appender-ref ref="fileAppender" />
</root>

</log4j:configuration>

We want our application to be writing to its own log for readability and convenience purposes. I also made some changes to the log statement formatting; the fully qualified name and line number has been removed as it is a performance hog and I added a literal "<EOR>" to delineate between log statements.

And that is it! Just make sure you place the log4j.xml file in the correct folder and everything should be working correctly! There are a few features like rolling logs that log4j offers which may be more useful in situation like this, but for brevity of an already long article I will cover that and a few other topics in a future article. If you have any question or comments let me know!

Sources:
http://logging.apache.org/log4j/1.2/manual.html
http://wiki.apache.org/logging-log4j/Log4jXmlFormat
http://logging.apache.org/log4j/companions/extras/apidocs/org/apache/log4j/EnhancedPatternLayout.html

Technorati Tags: Java, Logging, Web development

No related posts.