Tuesday, February 26, 2008

Log4j and the Art of Logging

Log4j has evolved as the preferred logging mechanism for java developers now. This post is for those who are new to logging using log4j.

As you know, log4j is an Open Source logging API from Apache. The current stable version is 1.2.1.5. You must download the log4j1.2.1.5 jar and add it to your classpath to work with the log4j APIs.

Log4j uses external configuration files. This can be either a log4j.properties file or log4j.xml file, which should be available in the classpath for log4j to work.

The basic building blocks of log4j are called Loggers(or Categories in versions prior to 1.2). The loggers receives log requests from Applications, and forwards these requests to appropriate destinations(called appenders) like console, files etc. The appenders will print the log statement in a format specified by the Layouts.

Loggers can be assigned Priority Levels - DEBUG, INFO, WARN, ERROR or FATAL. This is in ascending order of Priority levels. A logger will only print those statements directed to it, which has a priority greater than or equal to its assigned priority.

A logger will also be configured to use an Appender. This is where you specify the kind of destination, the file path, and any other parametsrs.

A root logger always exists which can be accessed from the application using the getRootLogger() static method of the Logger class. This has a default priority level of DEBUG, unless otherwise specified. All other loggers inherits the properties of root logger unless specified explicitly.

Appenders Can have Layouts associated with them, which specifies the format of a log entry. You can choose from the available Layouts like SimpleLayout, PatternLayout, HTMLLayout, dateLayout etc, or create your own. SimpleLayout prints the logs message along with the Log Level.
PatternLayout depends on a Conversion Pattern, to format the string. This pattern is like the pattern argument of the format() method of JDK 1.5 or the printf statement in C. Like in these methods, we can configure any static text that needs to be printed in the messages.

Here is a sample Conversion Pattern.

"%d{dd MMM yyyy HH:mm:ss} %-5p [%C{1}] {%t} %m"

%d{dd MMM yyyy HH:mm:ss} - Date in dd MMM yyyy HH:mm:ss format
%-5p - Priority of the Log Message
[%C{1}] - Name of the class from which the message is logged in square brackets
{%t} - Name of the thread that generated the log in curly brackets
%m - The log message from the application


Putting it all together, here is a sample log4j.xml file, with two loggers, each having their own Appenders.

The Struts Action class below, makes use of this XML file to log info and error messages to two differet files.
Make sure that the log4j.xml and the log4j1.2.1.5.jar(or any new version) are available in your classpath, before running this sample.




package com.classic.account.action;


import org.apache.log4j.Logger;
import org.apache.struts.action.*;
import javax.servlet.http.*;
import javax.servlet.*;

import com.classic.account.db.*;
import com.classic.account.util.*;
import com.classic.account.forms.*;

public class LoginAction extends Action
{
public ActionForward execute(ActionMapping mapping,ActionForm form,HttpServletRequest request,HttpServletResponse response) throws Exception
{

Logger errlog = Logger.getLogger("ClassicErrors");
Logger inflog = Logger.getLogger("ClassicInfo");
inflog.info("Starting User Authentication");
LoginForm lForm = (LoginForm)form;
String userId = lForm.getUserId();
String password = lForm.getPassword();
String userRole = lForm.getUserRole();
ActionErrors actionErrors = null;
try
{
User user = AccountDAO.getDAO().getUserAuthentication(userId);
if(user == null)
{
actionErrors = new ActionErrors();
actionErrors.add("GlblErrMsg", new ActionError("auth.failure"));
saveErrors(request,actionErrors);
inflog.info("Username Not Specified");
return mapping.findForward("failure");
}
else
{
String retPassword = user.getPassword();
if(!retPassword.equals(MD5Encrypt.getInstance().encrypt(password.trim())))
{
actionErrors = new ActionErrors();
actionErrors.add("GlblErrMsg", new ActionError("global.error"));
actionErrors.add("InvPasWd", new ActionError("password.failure"));
inflog.info("Invalid Password");
saveErrors(request,actionErrors);
return mapping.findForward("failure");
}
else
{
String retRoles = user.getUserRoles();
if(retRoles.indexOf(userRole) == -1 )
{
actionErrors = new ActionErrors();
actionErrors.add("GlblErrMsg", new ActionError("global.error"));
actionErrors.add("InvUsrRole", new ActionError("role.failure"));
inflog.info("User Role Mismatch");
saveErrors(request,actionErrors);
return mapping.findForward("failure");

}
else
{
//Success
request.getSession().setAttribute("AuthUser", user);
request.getSession().setAttribute("UserRole", userRole);
inflog.info("Authenticated Successfully!");
return mapping.findForward("success");
}
}
}
}
catch (Exception e)
{
actionErrors = new ActionErrors();
actionErrors.add("GlblErrMsg", new ActionError("exception.occurred"));
saveErrors(request,actionErrors);
errlog.error("Exception Occurred while Authenticating User.");
return mapping.findForward("failure");
}

}
public LoginAction()
{
super();
}
}


On execution of this class, two files - ClassicInf.log and ClassicErr.log will get created under D:/jakarta-tomcat-5.0.28/logs directory.

On a successful login attempt, the file ClassicInf.log will contain the following lines:

2008-02-26 10:42:17,122 21609 INFO [LoginAction] {http-8091-Processor24} Starting User Authentication
2008-02-26 10:42:17,231 21718 INFO [LoginAction] {http-8091-Processor24} Authenticated Successfully!

In case of an exception, the file ClassicErr.log will have this:

2008-02-26 10:47:23,412 21834 ERROR [LoginAction] {http-8091-Processor24} Exception Occurred while Authenticating User.

No comments: