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.

Jakarta Commons HttpClient

Ever wondered how to set a timeout of your choice in a java client application that communicates to a server side component?

You cannot use java.net.URLConnection in this case, because URLConnection doesnot support timeouts.

The solution is to use the Open source Jakarta Commons HttpClient API.
This is a robust API in terms of functionalities including cookie handling, secure communication(SSL), various authentication mechanisms, connection over a proxy etc.
It implements HTTP 1.0 and 1.1 and supports all HTTP methods.

Here is a sample code that submits a form data over a Post method, and prints the response. Instead of waiting indefenitely, the request will timeout after waiting for response after 10 seconds.

package jims;

import org.apache.commons.httpclient.*;
import org.apache.commons.httpclient.methods.*;
import org.apache.commons.httpclient.params.HttpMethodParams;

import java.io.*;
import java.net.SocketTimeoutException;

public class TimeOutTest {

private static String url = "http://localhost:8091/Classic/login.do";

public static void main(String[] args) {
//Instantiate the HttpClient and PostMethod
HttpClient client = new HttpClient();
HttpMethod method = new PostMethod(url);
//or GetMethod(url) as the case may be
try {
//Sets the Retry Handler. This will try to resend the request upto 3 times.
method.getParams().setParameter(HttpMethodParams.RETRY_HANDLER, new DefaultHttpMethodRetryHandler(3, false));
//Sets the Timeout value - in milliseconds
method.getParams().setSoTimeout(10000);
//Sets the form data - Key value Pairs
NameValuePair form_data [] = new NameValuePair[3];
form_data [0]= new NameValuePair("userId","yyyyy");
form_data [1]= new NameValuePair("password","xxxxxx");
form_data [2]= new NameValuePair("userRole","ZZZZZ");
method.setQueryString(form_data);
//Execute the Method
System.out.println("START:"+System.currentTimeMillis());

//Check the Response Code and print response
int statusCode = client.executeMethod(method);

if (statusCode != 200) //SC_OK
{
System.err.println("Error Occurred: " + method.getStatusLine());
}

byte[] responseBody = method.getResponseBody();

System.out.println(new String(responseBody));

}
catch (HttpException e)
{
System.err.println("Fatal protocol violation: " + e.getMessage());
}
catch (SocketTimeoutException e)
{
System.err.println("Request Timed Out!");
System.out.println("END:"+System.currentTimeMillis());
}
catch(Exception e)
{
e.printStackTrace();
}
finally {
//Finally, release the Connection
method.releaseConnection();
}
}
}

Please note that the socket timeout can be set at multiple layers of the request. It can be set at the method level(which we just experimented). It can also be set at the Connection level and the ConnectionManager level. Refer the Apache Commons HttpClient API Documentation for more information.

You need to have commons-httpclient-3.1.jar added to your classpath before running this example. Download the ZIP file, extract the jar and add it in the classpath.

You might have to download and add to classpath Apache Commons Logging and Commons Codec Jars if they are not there already, as the HttpClient API has dependancy on these two.