Homepage of Ingo Klöckl
 Home
 Programmieren
 - Toolbox
 - Java
 - PostScript
 - Perl
 - Assembler
 - Links
 - Download
Ingo Klöckl
i.kloeckl@2k-software.de

Logging with log4j

Basics

Log4j uses a set of hierarchical loggers, which inherit from a root logger. All logger are identified by their names, which may contain dots to indicate that a logger inherits from a parent logger. The inheritance includes output format as well as a threshold value, which limits the amount of messages actually passing the logger. These log levels are the following: 

DEBUG, INFO, WARN, ERROR, FATAL
You set them by using one of the following log statements: 
oLogger.debug(String pstrMessage)
oLogger.info(String pstrMessage)
oLogger.warn(String pstrMessage)
oLogger.error(String pstrMessage)
oLogger.fatal(String pstrMessage)
Setting a logger to a threshold of DEBUG means that all of these statements can pass their message to the logging media; setting it to WARN means, that only the warnings and error messages can pass the logger and actually be logged.

Using the loggin system in your code

To use the logging system in your code, you have to create one or more instances of Logger, using the logger name, which may be anyone of the configured loggers, including any of the child loggers. For this example, we use a logger hierarchy like the following: 

root                       logs to console and error file, INFO and higher
  root.general             logs to console and error file, INFO and higher
    root.general.config    logs to console and error file, INFO and higher
  root.algorithmus         logs to console and error file, DEBUG and other messages
File                       logs to sucess file, INFO and higher
We want a general logger (root.general) for all general logging output. The configuration section of the code should by logged separatedly, so we create another logger root.general.config for this, which may be configured independently from other program section, if desired (e.g. switched off later). All these loggers inherit from the root logger, which is configured to log only informational or errorneous messages.
Furthermore, for implementing the algorithm, we want another independent logger root.algorithmus, which is clearly separated from the general logger. This way, we can switch off the complete algorithmic section of the code later, if it runs errorfree. At the moment, this logger can separatedly configured to log also debug messages, without touching the general logging section. Note that we want all of these loggers to log warnings or error messages also in a file test.err, so we configure these loggers to write to the console as well as a file.
At last, we want a file logger (File), getting only messages about a successful run for storing. This logger inherits from the root logger, too, but will be configured to act independently from the root logger.

Now we will see the test program for the logging facility with heavy overdue of logging statements: 
import org.apache.log4j.Logger;
import org.apache.log4j.PropertyConfigurator;

public class Logtest {
	public static void main(String args[]){
		Logger oLog = Logger.getLogger("root");
		Logger oLogGen = Logger.getLogger("root.general");
		Logger oLogCfg = Logger.getLogger("root.general.config");
		Logger oLogFileOK = Logger.getLogger("File");
		PropertyConfigurator.configure("log.properties");

		oLogGen.debug("Starting program");

		if (args.length!=1) {
			oLogCfg.error("Error: missing parameter");
			System.exit(0);
		}
		int n = 0;
		try {
			n = Integer.parseInt(args[0]);
		} catch (NumberFormatException nfe){
			oLogCfg.error("Error: not an integer");
			System.exit(0);
		}
		oLogCfg.info("Running program with n="+n);

		if (n>10){
			oLogCfg.warn("Parameter limited to 10");
			n = 10;
		}

		oLog.debug("calling function");
		long lStart = System.currentTimeMillis();
		int erg = getSum(n);
		long lEnd = System.currentTimeMillis();
		oLog.debug("function call finished successfully");
		oLog.info("Result for "+n+" is "+erg);
		oLogGen.info("Calculation took "+(lEnd-lStart)+" ms");
		oLogFileOK.info("Result for "+n+" is "+erg);

		oLogGen.debug("Stopping program");
	}

	private static int getSum(int piMax){
		Logger oLogAlg = Logger.getLogger("root.algorithmus");
		oLogAlg.debug("Entering function with param "+piMax);
		int erg = 0;
		for (int i=0; i<piMax; i++){
			oLogAlg.debug("Loop with i="+i+", erg is "+erg);
			erg += i;
		}
		oLogAlg.debug("Returning from function");
		return erg;
	}
}

Configuring the logging system

To achive the desired logging possibilities, we have to configure the root logger with a threshold of INFO; most of the root... logger, especially the root.general... logger, inherit this from the root logger. The root logger writes its output to the console and a file, using the appenders stdout and fileerr. Only the algorithm logger must be individually configured to use a threshold of DEBUG.
Because we want only warnings and error messages in the error log file, we set the threshold for the error file explicitly in the appender section of the configuration. This gives us the change of changing the threshold only for the file appender, not for the console output.
The logger for the success file fileok is configured with a threshold of INFO, but note that the additivity of this logger is set to false. Normally, this logger inherits from the root logger, too (even if this is not expressed in the manually given name File, what would cause this logger writing to the console and the error file, too. To suppress this, we set the additivity to false, meaning that this logger is independent of the root logger.

Now let have a look at the config file log.properties: 
# logger structure:
#
# Logger name                Output to console  Output to success file  Output to err file
# root                       >=INFO             no                      >=WARN
#   root.general             >=INFO             no                      >=WARN
#     root.general.config    >=INFO             no                      >=WARN
#   root.algorithmus         >=DEBUG            no                      >=WARN
# File                       no                 >=INFO                  no

# basic settings ------------------------

# overall log level is INFO (includes categories root, root.general and
# root.general.config)
# we use the appender named 'stdout' as well as 'fileerr' to log errors
log4j.rootLogger=INFO, stdout, fileerr
# we are interested in the algorithm, so we increase the log level for this
# category to DEBUG
log4j.logger.root.algorithmus=DEBUG

# we need another appender for logging succesful runs in a disk file
# we name it 'fileok'
# the additivity is set to false, because all output for logger 'File' would
# be duplicated in the console output otherwise (because 'File' is inserted
# under the root logger, too)
log4j.logger.File=INFO, fileok
log4j.additivity.File=false


# settings of the root appender ---------------------

# console appender which is named 'stdout'
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d [%t] %-5p %c %x -%m%n

# appender which is named 'fileerr'
log4j.appender.fileerr.Threshold=WARN
log4j.appender.fileerr=org.apache.log4j.RollingFileAppender
log4j.appender.fileerr.File=test.err
log4j.appender.fileerr.MaxFileSize=100KB
log4j.appender.fileerr.MaxBackupIndex=1
log4j.appender.fileerr.layout=org.apache.log4j.PatternLayout
log4j.appender.fileerr.layout.ConversionPattern=%d [%t] %-5p %c %x -%m%n



# settings of the file appender ---------------------
# appender which is named 'fileok'
log4j.appender.fileok=org.apache.log4j.RollingFileAppender
log4j.appender.fileok.File=test.log
log4j.appender.fileok.MaxFileSize=100KB
log4j.appender.fileok.MaxBackupIndex=1
log4j.appender.fileok.layout=org.apache.log4j.PatternLayout
log4j.appender.fileok.layout.ConversionPattern=%d [%t] %-5p %c %x -%m%n

The output

To give you an impression of how the output of the test program looks like, here is the console output: 

2003-01-01 10:11:21,376 [main] INFO  root.general.config  -Running program with n=50
2003-01-01 10:11:21,376 [main] WARN  root.general.config  -Parameter limited to 10
2003-01-01 10:11:21,386 [main] DEBUG root.algorithmus  -Entering function with param 10
2003-01-01 10:11:21,386 [main] DEBUG root.algorithmus  -Loop with i=0, erg is 0
2003-01-01 10:11:21,386 [main] DEBUG root.algorithmus  -Loop with i=1, erg is 0
2003-01-01 10:11:21,386 [main] DEBUG root.algorithmus  -Loop with i=2, erg is 1
2003-01-01 10:11:21,386 [main] DEBUG root.algorithmus  -Loop with i=3, erg is 3
2003-01-01 10:11:21,386 [main] DEBUG root.algorithmus  -Loop with i=4, erg is 6
2003-01-01 10:11:21,386 [main] DEBUG root.algorithmus  -Loop with i=5, erg is 10
2003-01-01 10:11:21,386 [main] DEBUG root.algorithmus  -Loop with i=6, erg is 15
2003-01-01 10:11:21,386 [main] DEBUG root.algorithmus  -Loop with i=7, erg is 21
2003-01-01 10:11:21,386 [main] DEBUG root.algorithmus  -Loop with i=8, erg is 28
2003-01-01 10:11:21,386 [main] DEBUG root.algorithmus  -Loop with i=9, erg is 36
2003-01-01 10:11:21,386 [main] DEBUG root.algorithmus  -Returning from function
2003-01-01 10:11:21,386 [main] INFO  root  -Result for 10 is 45
2003-01-01 10:11:21,386 [main] INFO  root.general  -Calculation took 0 ms
Setting the threshold of the algorithm logger to INFO would fade out all debug messages from this section: 
2003-01-01 10:11:21,376 [main] INFO  root.general.config  -Running program with n=50
2003-01-01 10:11:21,376 [main] WARN  root.general.config  -Parameter limited to 10
2003-01-01 10:11:21,386 [main] INFO  root  -Result for 10 is 45
2003-01-01 10:11:21,386 [main] INFO  root.general  -Calculation took 0 ms
Setting the threshold of the general logger to WARN would further fade out all messages besides the really basic ones: 
2003-01-01 10:11:21,376 [main] WARN  root.general.config  -Parameter limited to 10
2003-01-01 10:11:21,386 [main] INFO  root  -Result for 10 is 45
The error log contains entries like these: 
2003-01-01 09:37:41,652 [main] ERROR root.general.config  -Error: missing parameter
2003-01-01 09:37:51,927 [main] WARN  root.general.config  -Parameter limited to 10
2003-01-01 09:38:33,927 [main] WARN  root.general.config  -Parameter limited to 10
2003-01-01 09:38:50,040 [main] WARN  root.general.config  -Parameter limited to 10
And, finally, the success log is the smallest: 
2003-01-01 09:37:51,937 [main] INFO  File  -Result for 10 is 45
2003-01-01 09:38:33,947 [main] INFO  File  -Result for 10 is 45
2003-01-01 09:38:50,040 [main] INFO  File  -Result for 10 is 45

Using Map contexts

In a multi-threaded application, as for example a J2EE application, it is possible that several threads access the same class at the same time, yielding multiple log entries with the same class as source. It is then difficult to distinguish the log entries from a single thread from that of another thread without further information.

It is possible and easy to give the logger additional information to be printed out. Look at the following example code: 

import org.apache.log4j.*;

...

String strUser = <get name of current user (valid for this thread!)>
MDC.put("user", strUser);
logger.debug("entering servlet");
...
logger.debug("do something");
...
logger.debug("exiting servlet");
MDC.remove("user");
The layout pattern for the logger is defined as follows: 
%d{ABSOLUTE} %-5p %c{1} [%X{user}] %m%n"
We have used an object from log4j called MDC, which essentially is a map of keys and values. Here, the key is user and contains the name of the current user of the servlet. This value is stored in the map and can be used in the logging output, using the pattern specifier %X{user} (where user may be replaced by whatever your map key was called). After the block in question, the key is removed from the map.

Now, assuming that the users Ingo and Claudia are accessing the code in two different threads, we get this logging output: 

2003-01-01 09:38:33,947 [main] DEBUG myservlet [ingo] entering servlet
2003-01-01 09:38:33,947 [main] DEBUG myservlet [claudia] entering servlet
2003-01-01 09:38:33,947 [main] DEBUG myservlet [ingo] do something
2003-01-01 09:38:33,947 [main] DEBUG myservlet [ingo] exiting servlet
2003-01-01 09:38:33,947 [main] DEBUG myservlet [claudia] do something
2003-01-01 09:38:33,947 [main] DEBUG myservlet [claudia] exiting servlet
The addition information makes it easy to distinguish the individual threads.

Using the loggin system in JBoss

It is easy to log events in JBoss with log4j, because this logging system is already used for internal JBoss logging. You may use it for yourself by modifying the file log4j.xml in the directory $jboss/server/default/conf. For this example, we modify the configuration as follows (note that for JBoss, you have to use the XML version of the configuration file, but in principle, all remains the same as with the property file format): 
... original file content ...

  <appender name="MYFILE" class="org.jboss.logging.appender.RollingFileAppender">
    <param name="File" value="${jboss.server.home.dir}/log/my.log"/>
    <param name="Append" value="false"/>
    <param name="MaxFileSize" value="500KB"/>
    <param name="MaxBackupIndex" value="1"/>

    <layout class="org.apache.log4j.PatternLayout">
      <param name="ConversionPattern" value="%d %-5p [%c{1}] %m%n"/>
    </layout>	    
  </appender>

  <appender name="MYCONSOLE" class="org.apache.log4j.ConsoleAppender">
    <param name="Target" value="System.out"/>
    <layout class="org.apache.log4j.PatternLayout">
      <param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%c{1}] %m%n"/>
    </layout>
  </appender>

  <logger name="de.kksoftware" additivity="false">
    <level value="INFO" />
    <appender-ref ref="MYCONSOLE"/>
    <appender-ref ref="MYFILE"/>
  </logger>
  <logger name="de.kksoftware.servlets" additivity="false">
    <level value="DEBUG" />
    <appender-ref ref="MYCONSOLE"/>
  </logger>

  <!-- ======================= -->
  <!-- Setup the Root category -->
  <!-- ======================= -->

  <root>
    <appender-ref ref="CONSOLE"/>
    <appender-ref ref="FILE"/>
  </root>

... rest of original file follows here ...
What we want is logging output for our own classes in a file and the console, too. For productive use, we want only catch informational (and higher-level) messages. Only for our servlets, we want also the debugging output, but only logged to the console. The JBoss-specific message should be logged as specified by the default configuration.

Therefore we have defined two additional appenders MYFILE and MYCONSOLE, one for logging into a file using INFO as threshold, the second for the console output. All classes under the package de.kksoftware logs both into the console and the file, and all servlets from the package de.kksoftware.servlets log only to the console, having a DEBUG threshold.

You may use the above loggers as usual, an example is given here for a servlet: 

package de.kksoftware.servlets;

import org.apache.log4j.*;

public abstract class ExampleServlet extends HttpServlet {

  protected Logger m_oLog;

  public void init(ServletConfig poConfig) throws ServletException {
    super.init(poConfig);
    m_oLog = Logger.getLogger(this.getClass().getName());
    m_oLog.debug("servlet "+this.getClass().getName()+" initialized");
  }

  public void doPost(HttpServletRequest req, HttpServletResponse res) throws ServletException, IOException {
    ...
    m_oLog.info("Servlet called");
    ...
  }
Note how the class name is used as logger name while getting a logger instance by simply calling this.getClass().getName(). (You are still free to specify another name by giving it literally.) The logging mechanism can be used from JSPs, too, by getting a logger instance as follows (using de.kksoftware.jsp as the root logger for the JSPs): 
<%@ page language="java" session="true" %>
<%@ page import="org.apache.log4j.Logger" %>
<%
	Logger oLog = Logger.getLogger("de.kksoftware.jsp.myJspPage");
	oLog.debug("query is "+request.getQueryString());
%>

You can see that there is nothing mysterious in logging in JBoss. In fact, it is even more simple than logging in your own programs, because reading of configuration files is already done by JBoss.

It is also worth to mention that JBoss does look up the configuration file regularly (every one or two minutes) for modifications. That means, after changing the config file and waiting a little bit, your running J2EE application uses the new logging settings without restarting it!

back to toolbox page