Setting up log4j in your Java Project

For those that are wondering about the need for a logging utility in their project when there are already debuggers, you might want to read the following passage from the book "The Practice of Programming": 

As personal choice, we tend not to use debuggers beyond getting a stack trace or the value of a variable or two. One reason is that it is easy to get lost in details of complicated data structures and control flow; we find stepping through a program less productive than thinking harder and adding output statements and self-checking code at critical places. Clicking over statements takes longer than scanning the output of judiciously-placed displays. It takes less time to decide where to put print statements than to single-step to the critical section of code, even assuming we know where that is. More important, debugging statements stay with the program; debugging sessions are transient.

Log4j is a Java-based logging utility and is a project of the Apache Software Foundation.
To add log4j to your project, first you will have to download it to your lib folder in your project. Make sure to add it to your classpath. If you are using Eclipse, just right click on the jar file in the lib directory, and go to Build Path -> Add to Build Path.
This tutorial is going to cover configuring log4j via a properties file called "log4j.properties". Configuring can also be done with a different technique using XML. 
It is considered a good coding practice to include your log4j.properties file in a "config" directory. 
Another library that we will be using for the purpose of this tutorial is the DatedFileAppender library. 

---

The source code for the following example:
Download link of zipped file: source

---

This is the file we will be using for our small project: 

log4j.rootLogger=DEBUG, TestLog

# logs to a DatedFile
log4j.appender.TestLog=biz.minaret.log4j.DatedFileAppender
log4j.appender.TestLog.Directory=./logs/
log4j.appender.TestLog.Prefix=log4j-test.
log4j.appender.TestLog.Suffix=.log
log4j.appender.TestLog.layout=org.apache.log4j.PatternLayout
log4j.appender.TestLog.layout.ConversionPattern=%d [%t] %-20.30c{1} %-5p %m%n

Let's analyze the config file above line by line. 

1. The first line specifies the root logger.  All loggers inherit from root, so in this example, all debug or higher severity messages from all loggers will be printed to the TestLog appender.  Here are the levels of severity that you can use to categorize your logging statements:
   1. TRACE
   2. DEBUG
   3. INFO
   4. WARN
   5. ERROR
   6. FATAL
   7. OFF
2. The next line (disregard the comment line) tells us that the appender named TestLog is a DatedFileAppender.
3. The line after that specifies the directory to which the log files will go. Don't bother to create the logs directory - it will be auto-created once the corresponding logger is invoked.
4. The prefix specifies the prefix of the file name that will come before the date.
5. The suffix specifies the suffix of the file name that will come after the date. If we were to run the program today it would result with a file named: log4j-test.2011-07-11.log
6. The next line is to specify which layout we want to use to specify the format of the logged messages. The PatternLayout lets the user specify the output format according to conversion patterns similar to the C language printf function.
7. This is where we specify the actual format:

   log4j.appender.TestLog.layout.ConversionPattern=%d [%t] %-20.30c{1} %-5p %m%n

   • %d - prints the date
   • %t - the name of the thread that logged the message
   • %c - the category of the logging event (in our case the Java class from which the logging event was called)
   • %p - the priority of the logging event (ex. DEBUG)
   • %m - the actual message
   • %n - the platfrom-specific newline character

Here is the starting class for our project - we will call it Startup.java. 

import org.apache.log4j.Logger;
import org.apache.log4j.PropertyConfigurator;

public class Startup {
   /** Logger for statistics. */
   protected static Logger logger
     = Logger.getLogger(Startup.class.getName());

   public static void main(String[] args) {  
      PropertyConfigurator.configure("./config/log4j.properties");
      logger.info("-> Start of program");  
      Record rec = new Record();
      rec.generateRecords(10);
      logger.info("<- End of program");
   }
}

The getLogger(String name) method of the Logger class will retrieve a logger with the name given as parameter - if a logger with the given name exists, then it will return you the existing instance. The level of the logger is inherited from the nearest ancestor. In our example it is the level of the root logger, which is DEBUG. 
The configure(String pathConfigFile) method of the PrppertyConfigurator class loads up the properties from our log4j.properties file. 
Here is the source code for the record class: 

import org.apache.log4j.Logger;

public class Record {

   /** Logger for statistics. */
   protected static Logger logger
     = Logger.getLogger(Record.class.getName());
 
   public void generateRecords(int numberOfRecords) {
      logger.info("-> generateRecords(" + numberOfRecords + ")" );
  
      for(int i = 0; i &lt < numberOfRecords; i++) {
         logger.debug("Record Nr. " + (i+1));
      }
      logger.info("<- generateRecords");
   }
}

Running Startup.java will result with a test file log4j-test.2011-07-11.log in the logs directory with the following contents: 

2011-07-11 18:30:16,901 [main] Startup              INFO  -> Start of program
2011-07-11 18:30:16,905 [main] Record               INFO  -> generateRecords(10)
2011-07-11 18:30:16,905 [main] Record               DEBUG Record Nr. 1
2011-07-11 18:30:16,905 [main] Record               DEBUG Record Nr. 2
2011-07-11 18:30:16,905 [main] Record               DEBUG Record Nr. 3
2011-07-11 18:30:16,905 [main] Record               DEBUG Record Nr. 4
2011-07-11 18:30:16,905 [main] Record               DEBUG Record Nr. 5
2011-07-11 18:30:16,905 [main] Record               DEBUG Record Nr. 6
2011-07-11 18:30:16,905 [main] Record               DEBUG Record Nr. 7
2011-07-11 18:30:16,905 [main] Record               DEBUG Record Nr. 8
2011-07-11 18:30:16,905 [main] Record               DEBUG Record Nr. 9
2011-07-11 18:30:16,906 [main] Record               DEBUG Record Nr. 10
2011-07-11 18:30:16,906 [main] Record               INFO  <- generateRecords
2011-07-11 18:30:16,906 [main] Startup              INFO  <- End of program

Now, let us say if we were to run this program in production, we would want to change the level of the root logger to INFO or something with a higher severity than that - to avoid logging messages which we would usually log only in a testing environment. So changing the level of the root logger to INFO: 

log4j.rootLogger=INFO, TestLog

results with the logging events having DEBUG level to be ignored in the logging process: 

2011-07-11 18:35:06,566 [main] Startup              INFO  -> Start of program
2011-07-11 18:35:06,568 [main] Record               INFO  -> generateRecords(10)
2011-07-11 18:35:06,568 [main] Record               INFO  <- generateRecords
2011-07-11 18:35:06,568 [main] Startup              INFO  <- End of program