Track Your Apps with the Open Source Logging Framework, Log4j

hey say ‘necessity is the mother of invention.’ Being able to keep an eye on your application is a need from which emerged logging and tracing frameworks. Application developers needed a way to have their programs relay vital signs and other signs of life to them. Many developers tend to use log statements as a low-tech approach to debugging. Such an approach is often leveraged in production, when you might not have the luxury of using your IDE’s debugger against your production code. Also, when things go wrong, you can trace the root of a problem using persisted logs.

Log4j is an open source logging API for Java, designed to be “reliable, fast, and extensible.” To the avail of programmers wanting to adopt an easy logging facility, Apache Log4j fits the mold.

Some Log4j Terminology
In the Log4j world:

  • Loggers are the workhorses for logging messages.
  • Appenders are associated to loggers and determine where log messages are reported.
  • Layouts define what your log messages will look like.
What You Need
At the time of this article’s writing, Log4j was in version 1.2.8. You can download the latest Log4j version from: http://logging.apache.org/log4j/docs/download.html.

Doing Some Logging
The code below is grabbed from the sample class SimpleLogger, which is included in the source code download for this article. The first thing I’ve done below is to get a Logger instance by using the getLogger static method of the org.apache.log4j.Logger class. It is this Logger object (which I called myLogger) that allows me to log.

Logger myLogger = Logger.getLogger("com.example.SimpleLogger");myLogger.setLevel(Level.WARN);// log events using the logger object// note that since we have associated a // level of WARN for our logger, we will not see the // INFO log statement// remember: DEBUG < INFO < WARN < ERROR < FATAL		 myLogger.info("I have dry mouth.");myLogger.warn("I am very thirsty");myLogger.error("I am dehydrated.");myLogger.fatal("I have died of thirst");

As you can see, logging is as simple as using the debug, info, warn, error, or fatal printing methods of the Logger object we get.

The output of the SimpleLogger class execution is shown below:

0 [main] WARN com.example.SimpleLogger  - I am very thirsty0 [main] ERROR com.example.SimpleLogger  - I am dehydrated.0 [main] FATAL com.example.SimpleLogger  - I have died of thirst

Developers are provided with different printing methods because Log4j allows us to set the level of logging that we want to see in our logs. In the code above, I set the level of the Logger programmatically using the setLevel method. However, this is usually done by grabbing the level from a configuration file, which I'll demonstrate in just a bit.

The possible levels of logging are ordered as follows:

DEBUG < INFO < WARN < ERROR < FATAL
Author's Note: Note that in Log4j, you are given the extensibility to create your own levels by subclassing the org.apache.log4j.Level class. However, Log4j proponents do not suggest it.

Log requests of a given level will find their way into the logs only if the printing method used corresponds with a log level greater than or equal to the level set for the Logger. Let's say, for example, I set the Logger's level to WARN. In this case, debug and info statements will not find their way into the logs, but warn, error, and fatal statements will. Similarly, if I set the Logger's level to FATAL, only fatal requests will be found in the logs; debug, info, warn, and error log requests will not be enabled.

Juxtapose this ability to pick and choose which log requests make it into your logs with the all-or-nothing approach of using System.out statements. It is not hard to see the value add of Log4j.

Naming Your Loggers and Understanding Logger Lineage
It is up to each programmer to establish a convention for naming his/her Logger instances. It is common Log4j practice to use the package-delineated name of the class for the name of the Logger. This way, when you scrutinize your logs, it is easier to pinpoint which class was responsible for the writing of a given log statement.

Author's Note: Logger names are case-sensitive.

Loggers follow a hierarchical naming rule. One Logger is an ancestor of another Logger if its name, predicated by a dot, is a prefix of another Logger. For example, com.ibm.test would be an ancestor of the so-called "descendant" Loggers ibm.test and test. Similarly, com.ibm.test is an ancestor of the descendant Logger test. If there are no ancestors between a given ancestor and a descendant, then those Loggers are referred to as parent and child Loggers, respectively.

Why should you care about this family lineage? In Log4j, logging levels are inherited. If you have not explicitly set a given Logger's logging level, the ancestry of the Logger in question will be scrutinized and moved, one by one, in the parent hierarchy until the first non-null level in the Logger hierarchy is reached. The Logger will then inherit this ancestor's level of logging.

Just as all objects in Java derive from the Object base class, all Loggers in Log4j can trace their ancestry back to the RootLogger Logger. The RootLogger always has an assigned level to ensure that if none of the descendant Loggers you create have their logging level explicitly specified, you can fall back on the logging level of the RootLogger (which is by default assigned to Level.DEBUG).

Interestingly enough, in the world of Log4j, the expression "I was born before my grandfather is valid." An example might best shed light on the subject. In short, I can create a Logger com.Grandfather.Grandson before I create the Logger com.Grandfather in my code. The parent Logger (com.Grandfather, in this example) will link to its descendent(s) (com.Grandfather.Grandson) when it is created.

Only One Logger
As your program execution jumps from method to method within your code, it would be quite annoying to have to pass Logger references between methods. Fortunately, you don't have to. When you use the getLogger method with the same name, you are always returned a reference to the same Logger object. In the code below, both loggerA and loggerB point to the same Logger object in memory:

Logger loggerA  = Logger.getLogger("com.someLogger");Logger loggerB = Logger.getLogger("com.someLogger");

Appenders?Choosing What Log4j Writes To
In the SimpleLogger sample code, the first statement is:

BasicConfigurator.configure();

This creates a basic Log4j setup that appends to the console. Dissecting one of our logs from the execution of SimpleLogger:

0 [main] WARN com.example.SimpleLogger  - I am very thirsty

What information does the log statement above impart? First, that the number of milliseconds elapsed from the start of the program is zero (0); it then identifies the thread making the request (main), the level of the log statement (WARN), the name of the Logger making the request (com.example.SimpleLogger); and finally, the log statement itself (I am very thirsty). In a moment, you will see how you can customize the layout of what information is reported to you in your logs.

Log4j allows the programmer to have his logs written to a number of different types of output destinations. In Log4j terminology, the output destination is referred to as an Appender. Log4j has appenders for writing to the console, to files, NT Event Loggers, and much more.

You can associate multiple appenders to a single Logger. You associate an appender to a Logger simply by calling the addAppender method. I demonstrate this in the sample class, AppenderExample, some of which is grabbed below:

// create a console appender	ConsoleAppender consoleAppender =      new ConsoleAppender(myLayout);// create a file appender RollingFileAppender rollingFileAppender = null;try {rollingFileAppender = new      RollingFileAppender(myLayout,"c:\log4joutput.log",true);               rollingFileAppender.setMaxFileSize("100KB");} catch(Exception e) {}Logger myLogger = Logger.getLogger("com.example.AppenderExample");// associate the appenders to the loggermyLogger.addAppender(consoleAppender);myLogger.addAppender(rollingFileAppender);

In the code above, I associated a ConsoleAppender as well as a RollingFileAppender to the Logger object. The ConsoleAppender simply writes to the screen as my previous BasicConfigurator approach did. However, the RollingFileAppender is a bit more interesting. It allows me to write logs to a file (which I specified will be located at c:log4joutput.log). I associated a Layout to each appender (which I will explain more about in the following section). Built into the RollingFileAppender is the ability to rollover files. Using the setMaxFileSize method, I state that once my log file reaches 100K, then older logs should automatically be moved to c:log4joutput.log.1, c:log4joutput.log.2, and so forth.

Adjusting Layout Using Patterns
The customizability of Log4j allows you to tailor the output of log statements to your liking. To customize the output format of your logs, you associate a layout to your appender (as I did in the AppenderExample sample class). Using an instance of org.apache.log4j.PatternLayout class, you can format your logging event as desired.

The PatternLayout object takes a conversion pattern string as an argument. It is this conversion pattern that will define the look of your log statements. These strings seem kind of perplexing (e.g., 4r [%t] %-5p %c %x - %m%n) The conversion pattern approach borrows from the C programming language, which uses a similar approach for its printf function.

The BasicConfigurator used in the SimpleLogger sample class uses a layout of: 4r [%t] %-5p %c %x - %m%n. As you saw from the sample output from that class, the default layout provides a good amount of information. However, we have a lot more information available to us (e.g., the time of the logging event and the line of the method in the code that wrote the log statement). You can learn more about how to tweak a conversion pattern string to your liking using the API for the PatternLayout class. I have provided a few demonstration formats in the sample class LayoutExample.

Configuring at Startup
As I stated earlier, one of the key capabilities of Log4j is being able to specify the configuration information at runtime. Previously, you set the level of logging using the setLevel method from the Logger instance.

myLogger.setLevel(Level.WARN);

This is not the usual way things are done in the real world. Rather, you would use the org.apache.log4j.PropertyConfigurator object as exemplified in PropertyConfiguratorExample.java to feed configuration information to your program at runtime. In the code, use the statement:

PropertyConfigurator.configure(args[0]);

to grab the name of the Log4j properties file when our program is fired up. The contents of the sample properties configuration file named logging.properties (also downloadable in the project zip file) are shown below:

# Set the root logger level to DEBUGlog4j.rootLogger=DEBUG, MyConsoleAppender# Set the logger level for com.example.PropertyConfigurator to errorlog4j.rootLogger=ERROR, MyConsoleAppender# create a ConsoleAppenderlog4j.appender.MyConsoleAppender=org.apache.log4j.ConsoleAppender# associate a pattern layout to the appenderlog4j.appender.MyConsoleAppender.layout=org.apache.log4j.PatternLayoutlog4j.appender.MyConsoleAppender.layout.ConversionPattern=%-4r [%t] %-5p %c %x - %m%n 

Provide the name and location of the logging properties file as the program argument (e.g., c:\logging.properties) to run the sample program.

Logging can have a material effect on the performance of your applications and should not be overlooked during your planning. See the sidebar "Performance Impact" to get some perspective on performance overhead with Log4j.Some Advanced Log4J Logging
What you've learned thus far in this article is quite likely to meet most of your logging needs. The next step is to make our study of Log4j a bit more invasive, demonstrating usage of some of the appenders bundled with the Log4j distribution, namely, NTEventLogAppender and JMSQueueAppender.

The NTEventLogAppender
If you are using a Windows environment for your Java applications to run in, then you might wish that certain log events from your Java programs could find their way to the NT Event logs so that an administrator in charge of viewing the logs could react when something goes awry. Log4j provides this "hook" into the NT Event logs.

As you will see shortly, an NT administrator can use the Event Viewer tool to examine events from the Java program that make their way into the NT event logs. Writing to the NT event logs is made simple by the NTEventLogAppender, which ships with Log4j. The one thing that you must do to make things work is place the file NTEventLogAppender.dll in a directory that is on the PATH of the Windows system (for example, in the C:windowssystem32 directory) or else you will get a java.lang.UnsatisfiedLinkError when trying to use the NTEventLogAppender.

The sample code below (taken from the Log4JWindowsNTEvent class, which is available in the downloadable sample code for this article) shows how to use the NTEventLogAppender.

// get a logger instance called "Log4JWindowsEvent"Logger myLogger = Logger.getLogger("Log4JWindowsNTEvent");// specify a sourceString mySource = "the source";// create an NTEventLogAppenderNTEventLogAppender eventLogAppender      = new NTEventLogAppender(mySource,myLayout);//create a console appender	ConsoleAppender consoleAppender = new ConsoleAppender(myLayout);// associate the appenders to the loggermyLogger.addAppender(consoleAppender);myLogger.addAppender(eventLogAppender);// set the level of the loggermyLogger.setLevel(Level.WARN);// log a fatal event myLogger.fatal("I have died of thirst");

As you can see, Log4j abstracts you from the intricacies of having to learn how to interface with the Windows API to write to the Event Log. All you have to do is construct an NTEventLogAppender (which I called eventLogAppender) and add this appender to your Logger (myLogger). I used the NTEventLogAppender(String source, Layout layout) constructor to specify the source of the event (which I called 'the source'). You can also do this with the setSource method.

To confirm that the event was logged to the NT Event Logs, you can use the Event Viewer application within the Windows Control Panel's Administrative Tools. Figure 1 shows the Windows Event Viewer in action, while Figure 2 shows how to get the details on the specific Log4j event from the application.


Figure 1. Momentous Events: The Event Viewer application can be used to view NT Events, including the sample Log4j log I wrote using the NTEventLogAppender.
 
Figure 2. Event Properties: Double-clicking on our event in the Event Viewer application gives us more information about the Log4j event we wrote.

The JMSQueueAppender
Today's distributed applications typically have software components residing on different physical machines. One could go about logging to individual files for each software component. However, it would be simpler to manage one centralized log file. To accomplish this, I will use asynchronous messaging and JMS. (For more on JMS, please read my earlier article, "Master JMS with OpenJMS.")

Author's Note: Log4j is designed to be thread safe; it allows for multiple applications/threads to log to the same log file. Therefore, JMS is not needed on a single machine set up.
Figure 3. Points to Point: The JMS provider manages a message queue that handles log entries from multiple points.

Log4j ships with a JMSAppender, which publishes messages to topics using a publish/subscribe messaging model. However, to make sure that log events are kept in sequence in a consolidated log file, a point-to-point set up is more desirable. I will thus leverage the Log4j JMSQueueAppender (contributed to the Apache Log4j project by Jamie Tsao).

The JMSQueue appender hasn't officially found its way into the final Log4j project code. However, you can get your hands on it by looking in the "contribsJamie Tsao" directory of the Log4j extract. Figure 3 depicts a typical setup in which each software component can use the JMSQueueAppender of Log4j to write to a JMS provider using a point-to-point messaging model. In essence, each software component that wishes to write to a consolidated log represents a 'point.' All 'points' write to a designated queue on our messaging provider (the end point in our points-to-point set up). Ultimately, a "collector" application can be used to gather the log messages written to the JMS provider's queues.

To demonstrate use of the JMS Appender, I'll use OpenJMS as the JMS provider. Log4JJMSQueueAppenderUsageExample is a class included in the sample code for this article. The code below is extracted from that class. As you can see, use the setters of the JMSQueueAppender to establish a connection to the queue named "queue1," which is a queue that the OpenJMS install preconfigures by default.

// create JMSQueueAppender// first specify connection properties to the JMS providerJMSQueueAppender jmsQueueAppender = new JMSQueueAppender();jmsQueueAppender.setInitialContextFactory("org.exolab.jms.jndi.InitialContextFactory");jmsQueueAppender.setProviderUrl("rmi://localhost:1099/");jmsQueueAppender.setQueueConnectionFactoryBindingName("JmsQueueConnectionFactory");// specify the queue we want to write tojmsQueueAppender.setQueueBindingName("queue1");// establish the connection to the queuejmsQueueAppender.activateOptions();

Because the log file being produced will be a composite of logs from different applications that might reside on different machines, it is a good idea to include this origination information in the log statements (so you know where a particular log came from). I did this by using the code:

java.net.InetAddress localMachine =     java.net.InetAddress.getLocalHost();String hostAddress = localMachine.getHostAddress());

When I log an event, I simply include this information in my log:

myLogger.fatal(hostAddress + " - I have died of thirst");
Author's Note: To aid your understanding, it is a good idea to have a couple of applications (preferably on different physical machines in a network) that will write to your logs.

After putting messages on the JMS provider's queue, as Figure 3 depicts, you still need a "sink" / collector application to consume the messages from the JMS provider and write them to a log file. Log4j ships with a sink application that uses the pub/sub messaging model. Because we are using the point-to-point messaging model, we need to build our own "sink."

I prebuilt a sink for you with the class MessageSink (see the sample code zip file). This message consumption application listens asynchronously to the queue that the JMSQueueAppender in our set up wrote to (queue1). (See the section named 'Asynchronous Retrieval' in my earlier article on OpenJMS.) I set up my connection to the queue of interest in my constructor, the code of which is shown below:

// create a JNDI contextHashtable properties = new Hashtable();properties.put(Context.INITIAL_CONTEXT_FACTORY,          "org.exolab.jms.jndi.InitialContextFactory");properties.put(Context.PROVIDER_URL, "rmi://localhost:1099/");Context context = new InitialContext(properties);// retrieve topic connection factoryQueueConnectionFactory queueConnectionFactory =     (QueueConnectionFactory) context.lookup("JmsQueueConnectionFactory");// create a queue connectionqueueConnection = queueConnectionFactory.createQueueConnection();// create a queue session// set transactions to false & set auto-ack of receipt of messagesqueueSession = queueConnection.createQueueSession(                         false,                         Session.AUTO_ACKNOWLEDGE);// retrieve queuequeue = (Queue) context.lookup("queue1");// create a queue receiver and associate to the retrieved queuequeueReceiver = queueSession.createReceiver(queue);// associate message listenerqueueReceiver.setMessageListener(this);// start delivery of incoming messagesqueueConnection.start();

The MessageSink class I provide implements the javax.jms.MessageListener interface and therefore is required to implement the onMessage method, via which it pulls messages off the message queue. In our onMessage message (shown below) is where I write messages to a log file. The callAppenders message allows me have my LoggingEvent sent to all the associated appenders I have registered. By analyzing the code of the MessageSink class, you'll see that I have registered two appenders, a RollingFileAppender and a ConsoleAppender.

// process incoming queue messagespublic void onMessage(Message message) {     LoggingEvent event;     try {          String messageText = null;          if (message instanceof ObjectMessage) {               ObjectMessage objectMessage                      = (ObjectMessage) message;               event = (LoggingEvent) objectMessage.getObject();               myLogger.callAppenders(event);          }     } catch (JMSException e) {     e.printStackTrace();     }}

To write to a log file I used (surprise, surprise) another Log4j appender, namely the org.apache.log4j.RollingFileAppender, which I created using the source below:

// create a rolling file appender RollingFileAppender rollingFileAppender = null;try {     // create a rolling file appender that writes to      // c:combinedlog4joutput.log     // the true argument of the constructor states that the      // file should be appended to, not written over     rollingFileAppender = new      RollingFileAppender(myLayout,"c:\combinedlog4joutput.log",true);     // set the rollover size to 100K     rollingFileAppender.setMaxFileSize("100KB");} catch(Exception e) {e.printStackTrace();}

By putting the example code to work, you should be able to see that your consolidated log file will contain the log events of all the software components which you have configured as participants in the setup.

Roll Your Own Appenders
Though it is beyond the scope of this article, Log4j allows you to write your own custom appenders. To do this, you need to derive from the org.apache.log4j.AppenderSkeleton class. This is precisely what Jamie Tsao did to create his JMSQueueAppender class, which we used on page 5 of this article.

So Popular, It Has Imitations
Version 1.3 of Log4j marked the 22nd major public release of Log4j. Log4j is continually and rigorously enhanced to optimize performance.

And it has gained a significant following among programmers. Before the advent of Java 1.4's innate logging facility (see the sidebar, "Log4j vs. the Java 1.4 Innate Language Logging Facility,"), Log4j was one of the most common logging facilities used by the Java programming community. Log4j has even been ported to the C, C++, C#, Perl, PHP, Python, Ruby, and Eiffel languages. And also be sure to read about the Performance Impact" of logging.

Check out some of these other articles on the Log4j site.

Share the Post:
Share on facebook
Share on twitter
Share on linkedin

Overview

The Latest

microsoft careers

Top Careers at Microsoft

Microsoft has gained its position as one of the top companies in the world, and Microsoft careers are flourishing. This multinational company is efficiently developing popular software and computers with other consumer electronics. It is a dream come true for so many people to acquire a high paid, high-prestige job

your company's audio

4 Areas of Your Company Where Your Audio Really Matters

Your company probably relies on audio more than you realize. Whether you’re creating a spoken text message to a colleague or giving a speech, you want your audio to shine. Otherwise, you could cause avoidable friction points and potentially hurt your brand reputation. For example, let’s say you create a

chrome os developer mode

How to Turn on Chrome OS Developer Mode

Google’s Chrome OS is a popular operating system that is widely used on Chromebooks and other devices. While it is designed to be simple and user-friendly, there are times when users may want to access additional features and functionality. One way to do this is by turning on Chrome OS